[vim/vim] Multiple, concurrent listener_add created callbacks made for the same change (#4438)
Paul Jolly
Describe the bug
Within govim, a format-on-save is achieved by adding a BufWritePre autocmd that makes a call to gopls for any changes that need to be applied pre-save. However it seems that when applying those changes (within the autocmd), multiple listener_add created callbacks are made for the same event.
To Reproduce
I have a repro of this and can either provide the precise steps for the repro or happily provide more logging/debug info as required. What follows is a description of the sequence of events. All calls from Vim to govim (whether autocmd handlers, commands or functions) use ch_evalexpr, i.e. they are blocking. The read loop within govim is separate from the processing of events.
- format-on-save triggered by
:wcommand - fires
BufWritePreautocmd - this is handled synchronously within
govimwhich makes a call togoplsfor any edits that need to be applied - still within the autocmd handler, the changes are applied, one by one
- the first change in our repro happens to be a call to
append() - this results, as expected, in a callback to our
listener_addfunction with the single change{"lnum":5,"col":1,"added":1,"end":5} govimis in the process of handling this change when we see another identical callback; i.e. to ourlistener_addcallback function, with{"lnum":5,"col":1,"added":1,"end":5}. Note at this stage we have not returned from the original callback (the logs show this to be the case)
We see the same callback 5 times in total.
These multiple callbacks also appear to be concurrent, i.e. the callback function has not returned from the first call before the second call is made by Vim. Things fall apart after we get the second callback because we are, at that point, in the process of trying to apply the second change from gopls... which fails because Vim thinks we should be handling the listener_add created callback (and hence the text is locked) and so we get the error message:
Caught 'Vim(let):E523: Not allowed here' in function <SNR>46_callbackAutoCommand[6]..GOVIM_internal_EnrichDelta[14]..GOVIM_internal_BufChanged[2]..<SNR>46_callbackFunction[2]..GOVIM_internal_EnrichDelta[14]..GOVIM_internal_BufChanged[2]..<SNR>46_callbackFunction[2]..<SNR>46_define, line 54
But I think this error is probably a red herring; we wouldn't run into this if we didn't get multiple callbacks.
Expected behavior
Not to receive multiple concurrent callbacks for the same change, unless I've massively misunderstood something.
Screenshots
n/a
Environment (please complete the following information):
- Vim version
VIM - Vi IMproved 8.1 (2018 May 18, compiled May 26 2019 10:54:21)
Included patches: 1-1397
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.
—
You are receiving this because you are subscribed to this thread.
Reply to this email directly, view it on GitHub
Andy Massimino
If I understand correctly, maybe listener callbacks should be collected and held until autocmds have been processed?
When you say "govim is in the process of handling this change", you mean while using ch_evalexpr? So vim is allowed to re-trigger the same listener callbacks during this time?
Generally, should changes be given a sequence number? It might help plugins keep track of things, and at the least it would help debug this case.
Paul Jolly
Note the attempt to apply the second edit (a line delete) fails
because Vim has locked the buffer at this point. (I have omitted the
return from the BufWritePre because of this error, i.e. everything
unwinds).
I don't think Vim should be calling the callback multiple times for
the same change, but I might have misunderstood something in the
listener_add changes.
> --
> You received this message from the "vim_dev" maillist.
> Do not top-post! Type your reply below the text you are replying to.
> For more information, visit http://www.vim.org/maillist.php
>
> ---
> You received this message because you are subscribed to the Google Groups "vim_dev" group.
> To unsubscribe from this group and stop receiving emails from it, send an email to vim_dev+u...@googlegroups.com.
> To view this discussion on the web visit https://groups.google.com/d/msgid/vim_dev/vim/vim/issues/4438/496249663%40github.com.
> For more options, visit https://groups.google.com/d/optout.
vim-dev ML
Note the attempt to apply the second edit (a line delete) fails
because Vim has locked the buffer at this point. (I have omitted the
return from the BufWritePre because of this error, i.e. everything
unwinds).
I don't think Vim should be calling the callback multiple times for
the same change, but I might have misunderstood something in the
listener_add changes.
On Mon, 27 May 2019 at 16:37, Andy Massimino <vim-dev...@256bit.org> wrote:
>
> If I understand correctly, maybe listener callbacks should be collected and held until autocmds have been processed?
>
> When you say "govim is in the process of handling this change", you mean while using ch_evalexpr? So vim is allowed to re-trigger the same listener callbacks during this time?
>
> Generally, should changes be given a sequence number? It might help plugins keep track of things, and at the least it would help debug this case.
>
> —
> Reply to this email directly, view it on GitHub
>
> --
> You received this message from the "vim_dev" maillist.
> Do not top-post! Type your reply below the text you are replying to.
> For more information, visit http://www.vim.org/maillist.php
>
> ---
> You received this message because you are subscribed to the Google Groups "vim_dev" group.
> To unsubscribe from this group and stop receiving emails from it, send an email to vim_dev+u...@googlegroups.com.
> To view this discussion on the web visit https://groups.google.com/d/msgid/vim_dev/vim/vim/issues/4438/496249663%40github.com.
> For more options, visit https://groups.google.com/d/optout.
—
You are receiving this because you are subscribed to this thread.
Reply to this email directly, view it on GitHub, or mute the thread.
Bram Moolenaar
> **Describe the bug**
>
> Within `govim`, a format-on-save is achieved by adding a `BufWritePre` autocmd that makes a call to `gopls` for any changes that need to be applied pre-save. However it seems that when applying those changes (within the autocmd), multiple `listener_add` created callbacks are made for the same event.
>
> **To Reproduce**
>
> I have a repro of this and can either provide the precise steps for the repro or happily provide more logging/debug info as required. What follows is a description of the sequence of events. All calls from Vim to `govim` (whether autocmd handlers, commands or functions) use `ch_evalexpr`, i.e. they are blocking. The read loop within `govim` is separate from the processing of events.
>
> * format-on-save triggered by `:w` command
> * fires `BufWritePre` autocmd
> * this is handled synchronously within `govim` which makes a call to `gopls` for any edits that need to be applied
> * still within the autocmd handler, the changes are applied, one by one
> * the first change in our repro happens to be a call to `append()`
> * this results, as expected, in a callback to our `listener_add` function with the single change `{"lnum":5,"col":1,"added":1,"end":5}`
> * `govim` is in the process of handling this change when we see _another_ identical callback; i.e. to our `listener_add` callback function, with `{"lnum":5,"col":1,"added":1,"end":5}`. Note at this stage we have _not_ returned from the original callback (the logs show this to be the case)
>
> We see the same callback 5 times in total.
>
>
> ```
> Caught 'Vim(let):E523: Not allowed here' in function <SNR>46_callbackAutoCommand[6]..GOVIM_internal_EnrichDelta[14]..GOVIM_internal_BufChanged[2]..<SNR>46_callbackFunction[2]..GOVIM_internal_EnrichDelta[14]..GOVIM_internal_BufChanged[2]..<SNR>46_callbackFunction[2]..<SNR>46_define, line 54
> ```
>
> But I think this error is probably a red herring; we wouldn't run into this if we didn't get multiple callbacks.
>
>
> Not to receive multiple concurrent callbacks for the same change, unless I've massively misunderstood something.
- Listeners need to be notified before some changes are made that would
make the reported changes invalid.
- Changes are being made while in the listener callback.
I'm actually not sure how changes can be made while in the listener
callback, that should not happen. Text is locked at that time.
I don't how Vim could postpone changes at this point.
Probably either the actions in the autocommand should be postponed, or
the listener callback should be to finish quickly.
--
Bumper sticker: Honk if you love peace and quiet.
/// Bram Moolenaar -- Br...@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 ///
—
You are receiving this because you commented.
Paul Jolly
Total fail from me before, replied to the email and forgetting that an attachment would not make it to this GitHub issue. Trying again :)
There was actually an error in my original analysis.
The following sequence diagram hopefully shows things more clearly.
In govim we have one go routine handling the read of messages from Vim which are then enqueued. Another go routine processes this queue; I've tried to illustrate this with two "threads" within govim
The thing that is causing govim to get into a muddle is the fact that the listener callback happens after Apply edit 1 return, because at that point govim has returned to processing the BufWritePre event. This results in govim trying to apply the second edit (a delete in this case) when Vim is in this locked state.
But I think this is my misunderstanding/error.
Instead of processing each edit in turn from govim, I think I need to send the batch of changes to Vim, process them within a loop, call listener_flush at the end of that loop (for good measure).
Does that sound about right to you @brammool?
—
You are receiving this because you commented.
Paul Jolly
Instead of processing each edit in turn from govim, I think I need to send the batch of changes to Vim, process them within a loop, call listener_flush at the end of that loop (for good measure).
I've done exactly as proposed above. On reflection, the change makes good logical sense because it's then always Vim that is responsible for handling edits to a buffer. This means I no longer get the error about the text being locked.
But I'm still seeing multiple, concurrent listener callbacks with the same argument. I don't know that I've established a pattern as yet:
The following sequence of calls:
appendbufline(...)
deletebufline(...)
results in the following sequence of listener callbacks:
{"lnum":5,"col":1,"added":1,"end":5}]]]
[{"lnum":4,"col":1,"added":-1,"end":5}]]]
[{"lnum":4,"col":1,"added":-1,"end":5}]]]
[{"lnum":4,"col":1,"added":-1,"end":5}]]]
If it's significant, my listener callback invokes ch_evalexpr, a govim provided function, and that govim function notifies gopls of the change.
—
You are receiving this because you commented.
Bram Moolenaar
Paul Jolly wrote:
> Hopefully the attached very rough sequence diagram helps to add a bit
> of colour
>
> Note the attempt to apply the second edit (a line delete) fails
> because Vim has locked the buffer at this point. (I have omitted the
> return from the BufWritePre because of this error, i.e. everything
> unwinds).
>
> I don't think Vim should be calling the callback multiple times for
> the same change, but I might have misunderstood something in the
> listener_add changes.
when a previous one hasn't finished yet. Then probably the list of
changes is messed up.
How can that happen? The text is locked, thus there can't actually be a
text change that triggers the callback. Can you figure out what
triggers the second callback invocation?
--
Everybody lies, but it doesn't matter since nobody listens.
-- Lieberman's Law
Bram Moolenaar
Paul Jolly wrote:
> Total fail from me before, replied to the email and forgetting that an attachment would not make it to this GitHub issue. Trying again :)
>
> There was actually an error in my original analysis.
>
> The following sequence diagram hopefully shows things more clearly.
>
>
> _In `govim` we have one go routine handling the read of messages from Vim which are then enqueued. Another go routine processes this queue; I've tried to illustrate this with two "threads" within `govim`_
>
> The thing that is causing `govim` to get into a muddle is the fact that the listener callback happens _after_ `Apply edit 1 return`, because at that point `govim` has returned to processing the `BufWritePre` event. This results in `govim` trying to apply the second edit (a delete in this case) when Vim is in this locked state.
>
> But I think this is my misunderstanding/error.
>
> Does that sound about right to you @brammool?
callbacks will be invoked halfway. Perhaps you can flush listeners
after every change you make from govim? Perhaps that's what you mean
with "at the end of that loop", thus not after the loop. That should be
OK then, since you make these text changes intentionally, thus I suppose
you don't need them to trigger a CodeAction.
--
Don't read everything you believe.
/// Bram Moolenaar -- Br...@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 ///
—
You are receiving this because you commented.
vim-dev ML
Paul Jolly wrote:
> Hopefully the attached very rough sequence diagram helps to add a bit
> of colour
>
> Note the attempt to apply the second edit (a line delete) fails
> because Vim has locked the buffer at this point. (I have omitted the
> return from the BufWritePre because of this error, i.e. everything
> unwinds).
>
> I don't think Vim should be calling the callback multiple times for
> the same change, but I might have misunderstood something in the
> listener_add changes.
It looks like the main problem is that a listener callback is invoked
when a previous one hasn't finished yet. Then probably the list of
changes is messed up.
How can that happen? The text is locked, thus there can't actually be a
text change that triggers the callback. Can you figure out what
triggers the second callback invocation?
--
Everybody lies, but it doesn't matter since nobody listens.
-- Lieberman's Law
/// 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 ///
—
Paul Jolly
If the changes that are made to the text have overlaps, the then
callbacks will be invoked halfway.
Indeed, that's why I receive the callback as a result of the append first and don't receive the two changes as part of a single callback.
I just tested:
- flushing the changes after each change
- flushing the changes at the end of the function that applies the batch of changes
Both fix things. When I say "fixes things" I mean I only get the two callbacks I expected, namely:
[{"lnum":5,"col":1,"added":1,"end":5}]
[{"lnum":4,"col":1,"added":-1,"end":5}]
It looks like the main problem is that a listener callback is invoked
when a previous one hasn't finished yet
Correct, that's what I meant by concurrently.
@brammool - do you want to look into this in any more detail? If there is any further debugging/investigation I can do with my test case (which is 100% reproducible if I don't flush the changes) then please let me know. Otherwise, assuming I don't run into any further issues, I'm tempted to suggest we mark this as closed?
—
You are receiving this because you commented.
Paul Jolly
I've just run into another issue... which actually causes me to question whether the listener_flush solution above is indeed a "solution".
In the case of govim it's easy for me to call listener_flush because I'm in control of the changes being made.
But, and this is the example I just ran into, if another plugin is the one making changes (https://github.com/tpope/vim-fugitive in this case) then we can't reasonably expect these plugins to now have to call listener_flush can we?
—
You are receiving this because you commented.
Bram Moolenaar
> I've just run into another issue... which actually causes me to
> question whether the `listener_flush` solution above is indeed a
> "solution".
>
> In the case of `govim` it's easy for me to call `listener_flush`
> because I'm in control of the changes being made.
>
> the one making changes (https://github.com/tpope/vim-fugitive in this
> case) then we can't reasonably expect these plugins to now have to
> call `listener_flush` can we?
somehow related to autocommands triggering a plugin to make changes?
In other words: how would another plugin interfere with your plugin,
since everything is single-threaded. Something must trigger code of the
other plugin to be executed.
--
George: "I just got a new set of golf clubs for my wife!"
John: "Great trade!"
/// Bram Moolenaar -- Br...@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 ///
—
You are receiving this because you commented.
Bram Moolenaar
> > If the changes that are made to the text have overlaps, the then callbacks will be invoked halfway.
>
> Indeed, that's why I receive the callback as a result of the `append` first and don't receive the two changes as part of a single callback.
>
> I just tested:
>
> * flushing the changes at the end of the function that applies the batch of changes
>
> Both fix things. When I say "fixes things" I mean I only get the two callbacks I expected, namely:
>
> [{"lnum":5,"col":1,"added":1,"end":5}]
> [{"lnum":4,"col":1,"added":-1,"end":5}]
> ```
>
> > It looks like the main problem is that a listener callback is invoked when a previous one hasn't finished yet
>
> Correct, that's what I meant by concurrently.
>
> @brammool - do you want to look into this in any more detail? If there is any further debugging/investigation I can do with my test case (which is 100% reproducible if I don't flush the changes) then please let me know. Otherwise, assuming I don't run into any further issues, I'm tempted to suggest we mark this as closed?
in a way I can add a test for it?
--
Well, you come from nothing, you go back to nothing... What have you
lost? Nothing!
-- Monty Python: The life of Brian
/// Bram Moolenaar -- Br...@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 ///
—
You are receiving this because you commented.
Paul Jolly
No, but isn't this similar to the user making changes?
Apologies, I think I've set the hares running prematurely in this instance; on further investigation it doesn't look to be a plugin or Vim problem, instead an issue on my side. Will report back.
Can you reproduce the problem of this "concurrently" callback invocation in a way I can add a test for it?
I have a repro, but that's only in the context of govim; I haven't been able to create a minimal repro of this. If you want to send me a patch that will do debug logging etc that's fine.
—
You are receiving this because you commented.
Paul Jolly
No, but isn't this similar to the user making changes?
Apologies, I think I've set the hares running prematurely in this instance; on further investigation it doesn't look to be a plugin or Vim problem, instead an issue on my side. Will report back.
This was indeed my error, apologies for the noise.
The issue of multiple concurrent callbacks remains however if I don't use listener_flush, so my offer of further debugging remains 😄
—
You are receiving this because you commented.
Bram Moolenaar
> > No, but isn't this similar to the user making changes?
>
> Apologies, I think I've set the hares running prematurely in this
> instance; on further investigation it doesn't look to be a plugin or
> Vim problem, instead an issue on my side. Will report back.
>
>
> I have a repro, but that's only in the context of `govim`; I haven't
> been able to create a minimal repro of this. If you want to send me a
> patch that will do debug logging etc that's fine.
callbacks. However, if an attempt is made then the list of changes may
be invalid.
What we can also do is block handling messages on channels, I suspect
that might solve your problem, since these messages may be handled
asynchronously, e.g. when checking for input.
Still, it would be useful to add a test for this.
--
hundred-and-one symptoms of being an internet addict:
46. Your wife makes a new rule: "The computer cannot come to bed."
/// Bram Moolenaar -- Br...@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 ///
—
You are receiving this because you commented.
Paul Jolly
I will add a flag to prevent recursive calls of invoking listener
callbacks.
Thanks, I can confirm that 68a4b04 fixes things, i.e. I no longer need the listener_flush call.
What we can also do is block handling messages on channels, I suspect
that might solve your problem, since these messages may be handled
asynchronously, e.g. when checking for input.
I'm not quite sure what you mean by "block handling messages on channels"?
—
You are receiving this because you commented.
Bram Moolenaar
> > I will add a flag to prevent recursive calls of invoking listener callbacks.
>
>
> > What we can also do is block handling messages on channels, I
> > suspect that might solve your problem, since these messages may be
> > handled asynchronously, e.g. when checking for input.
>
> I'm not quite sure what you mean by "block handling messages on channels"?
If this happens while in the listener callback, and the channel message
causes the text to change, we would get into the situation where the
listener callbacks would be invoked recursively. Causing some changes
not being reported in time.
I have already done that, so it should work better already.
--
hundred-and-one symptoms of being an internet addict:
/// Bram Moolenaar -- Br...@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 ///
—
You are receiving this because you commented.
Paul Jolly
I have already done that, so it should work better already.
Thanks for clarifying in any case.
I'm going to close this issue now because I think we're done here; only #4455 is outstanding from a govim delta perspective.
Thanks again for your persistence and patience in helping me work through this.
—
You are receiving this because you commented.