Make hover request asynchronous

The hover request is enabled by default on CursorHold. It's not uncommon
for &updatetime to be set to a small value for other plugings that
update on CursorHold (even YCM used to do this).

However, previously the Hover request was _blocking_. This meant that on
a fairly large codebase, by default YCM could block Vim for many seconds
particularly on startup.

This is YCM anathema, and a big error. Therfore, as it's not easy to
unwind the "enabled by default" decision, a better resolution is to make
the request asynchronous.

This change introduces a `youcompleteme#GetCommandResponseAsync` with
the same behaviour as `youcompleteme#GetCommandResponse` but taking a
callback to handle the result. This is in turn used by the YCMHover
mapping and autocommand.

README.md

@@ -2007,13 +2007,57 @@ conditions.
 The arguments to the function are the same as the arguments to the
 `:YcmCompleter` ex command, e.g. the name of the subcommand, followed by any
 additional subcommand arguments. As with the `YcmCompleter` command, if the
-first argument is `ft=<filetype>` the request is targetted at the specified
+first argument is `ft=<filetype>` the request is targeted at the specified
 filetype completer. This is an advanced usage and not necessary in most cases.
 
 NOTE: The request is run synchronously and blocks Vim until the response is
 received, so we do not recommend running this as part of an autocommand that
 triggers frequently.
 
+### The `youcompleteme#GetCommandResponseAsync( callback, ... )` function
+
+This works exactly like `youcompleteme#GetCommandResponse`, except that instead
+of returning the result, you supply a `callback` argument. This argument must be
+a `FuncRef` to a function taking a single argument `response`. This callback
+will be called with the command response at some point later, or immediately.
+
+As with `youcompleteme#GetCommandResponse()`, this function will call the
+callback with `''` (an empty string) if the request is not sent, or if there was
+some sort of error.
+
+Here's an example that's similar to the one above:
+
+```viml
+
+let s:ycm_hover_popup = -1
+function! s:ShowDataPopup( response ) abort
+  if response == ''
+    return
+  endif
+
+  call popup_hide( s:ycm_hover_popup )
+  let s:ycm_hover_popup = popup_atcursor( balloon_split( response ), {} )
+endfunction
+
+function! s:GetData() abort
+  call youcompleteme#GetCommandResponseAsync(
+    \ function( 's:ShowDataPopup' ),
+    \ 'GetDoc' )
+endfunction
+
+autocommand CursorHold * call s:GetData()
+```
+
+Again, see [`g:ycm_auto_hover`](#the-gycm_auto_hover-option) for proper hover
+support.
+
+**NOTE**: The callback may be called immediately, in the stack frame that called
+this function.
+
+**NOTE**: Only one command request can be outstanding at once. Attempting to
+request a second responses while the first is outstanding will result in the
+second callback being immediately called with `''`.
+
 Autocommands
 ------------
 

autoload/youcompleteme.vim

@@ -19,8 +19,6 @@
 let s:save_cpo = &cpo
 set cpo&vim
 
-let s:DEBUG = 0
-
 " This needs to be called outside of a function
 let s:script_folder_path = escape( expand( '<sfile>:p:h' ), '\' )
 let s:force_semantic = 0
@@ -51,6 +49,10 @@ let s:pollers = {
       \   'receive_messages': {
       \     'id': -1,
       \     'wait_milliseconds': 100
+      \   },
+      \   'command': {
+      \     'id': -1,
+      \     'wait_milliseconds': 100
       \   }
       \ }
 let s:buftype_blacklist = {
@@ -547,14 +549,6 @@ function! s:OnCompleteDone()
     return
   endif
 
-  if s:DEBUG
-    call ch_log( 'ycm: s:OnCompleteDone()' .
-               \ ' - last_char_inserted_by_user=' .
-               \ s:last_char_inserted_by_user .
-               \ ' - v:completed_item=' .
-               \ string( v:completed_item ) )
-  endif
-
   let s:last_char_inserted_by_user = v:false
 
   py3 ycm_state.OnCompleteDone()
@@ -567,14 +561,6 @@ function! s:OnCompleteChanged()
     return
   endif
 
-  if s:DEBUG
-    call ch_log( 'ycm: s:OnCompleteChanged()' .
-               \ ' - last_char_inserted_by_user=' .
-               \ s:last_char_inserted_by_user .
-               \ ' - v:event=' .
-               \ string( v:event ) )
-  endif
-
   if ! empty( v:event.completed_item )
     let s:last_char_inserted_by_user = v:false
   endif
@@ -743,14 +729,6 @@ function! s:OnInsertChar()
     return
   endif
 
-  if s:DEBUG
-    call ch_log( 'ycm: s:OnInsertChar()' .
-               \ ' - last_char_inserted_by_user=' .
-               \ s:last_char_inserted_by_user .
-               \ ' - v:char = ' .
-               \ v:char )
-  endif
-
   let s:last_char_inserted_by_user = v:true
 
   if s:completion_api == s:COMPLETION_COMPLETEFUNC
@@ -813,12 +791,6 @@ function! s:OnTextChangedInsertMode( popup_is_visible )
     return
   endif
 
-  if s:DEBUG
-    call ch_log( 'ycm: s:OnTextChangedInsertMode( ' . a:popup_is_visible . ')' .
-               \ ' - last_char_inserted_by_user=' .
-               \ s:last_char_inserted_by_user )
-  endif
-
   if a:popup_is_visible && !s:last_char_inserted_by_user
     " If the last "input" wasn't from a user typing (i.e. didn't come from
     " InsertCharPre, then ignore this change in the text. This prevents ctrl-n
@@ -1211,6 +1183,7 @@ function! s:RestartServer()
   py3 ycm_state.RestartServer()
 
   call s:StopPoller( s:pollers.receive_messages )
+  call s:StopPoller( s:pollers.command )
   call s:ClearSignatureHelp()
 
   call s:StopPoller( s:pollers.server_ready )
@@ -1254,6 +1227,51 @@ function! youcompleteme#GetCommandResponse( ... )
 endfunction
 
 
+function! youcompleteme#GetCommandResponseAsync( callback, ... )
+  if !s:AllowedToCompleteInCurrentBuffer()
+    eval a:callback( '' )
+    return
+  endif
+
+  if !get( b:, 'ycm_completing' )
+    eval a:callback( '' )
+    return
+  endif
+
+  if s:pollers.command.id != -1
+    eval a:callback( '' )
+    return
+  endif
+
+  py3 ycm_state.SendCommandRequestAsync( vim.eval( "a:000" ) )
+
+  let s:pollers.command.id = timer_start(
+        \ s:pollers.command.wait_milliseconds,
+        \ function( 's:PollCommand', [ a:callback ] ) )
+endfunction
+
+function! s:PollCommand( callback, id )
+  if py3eval( 'ycm_state.GetCommandRequest() is None' )
+    " Possible in case of race conditions and things like RestartServer
+    " But particualrly in the tests
+    return
+  endif
+
+  if !py3eval( 'ycm_state.GetCommandRequest().Done()' )
+    let s:pollers.command.id = timer_start(
+          \ s:pollers.command.wait_milliseconds,
+          \ function( 's:PollCommand', [ a:callback ] ) )
+    return
+  endif
+
+  call s:StopPoller( s:pollers.command )
+
+  let result = py3eval( 'ycm_state.GetCommandRequest().StringResponse()' )
+
+  eval a:callback( result )
+endfunction
+
+
 function! s:CompleterCommand( mods, count, line1, line2, ... )
   py3 ycm_state.SendCommandRequest(
         \ vim.eval( 'a:000' ),
@@ -1339,19 +1357,25 @@ if exists( '*popup_atcursor' )
       return
     endif
 
-    let response = youcompleteme#GetCommandResponse( b:ycm_hover.command )
-    if response == ''
-      return
-    endif
+    call youcompleteme#GetCommandResponseAsync(
+          \ function( 's:ShowHoverResult' ),
+          \ b:ycm_hover.command )
+  endfunction
+
 
+  function! s:ShowHoverResult( response )
     call popup_hide( s:cursorhold_popup )
 
+    if empty( a:response )
+      return
+    endif
+
     " Try to position the popup at the cursor, but avoid wrapping. If the
     " longest line is > screen width (&columns), then we just have to wrap, and
     " place the popup at the leftmost column.
     "
     " Find the longest line (FIXME: probably doesn't work well for multi-byte)
-    let lines = split( response, "\n" )
+    let lines = split( a:response, "\n" )
     let len = max( map( copy( lines ), "len( v:val )" ) )
 
     let wrap = 0
@@ -1382,6 +1406,7 @@ if exists( '*popup_atcursor' )
                             \ b:ycm_hover.syntax )
   endfunction
 
+
   function! s:ToggleHover()
     let pos = popup_getpos( s:cursorhold_popup )
     if !empty( pos ) && pos.visible
@@ -1406,6 +1431,10 @@ else
   nnoremap <silent> <plug>(YCMHover) <Nop>
 endif
 
+function! youcompleteme#Test_GetPollers()
+  return s:pollers
+endfunction
+
 " This is basic vim plugin boilerplate
 let &cpo = s:save_cpo
 unlet s:save_cpo

python/ycm/client/command_request.py

@@ -19,6 +19,8 @@ from ycm.client.base_request import BaseRequest, BuildRequestData
 from ycm import vimsupport
 from ycmd.utils import ToUnicode
 
+DEFAULT_BUFFER_COMMAND = 'same-buffer'
+
 
 def _EnsureBackwardsCompatibility( arguments ):
   if arguments and arguments[ 0 ] == 'GoToDefinitionElseDeclaration':
@@ -27,37 +29,51 @@ def _EnsureBackwardsCompatibility( arguments ):
 
 
 class CommandRequest( BaseRequest ):
-  def __init__( self,
-                arguments,
-                buffer_command = 'same-buffer',
-                extra_data = None ):
+  def __init__( self, arguments, extra_data = None, silent = False ):
     super( CommandRequest, self ).__init__()
     self._arguments = _EnsureBackwardsCompatibility( arguments )
     self._command = arguments and arguments[ 0 ]
-    self._buffer_command = buffer_command
     self._extra_data = extra_data
     self._response = None
     self._request_data = None
+    self._response_future = None
+    self._silent = silent
 
 
-  def Start( self, silent = False ):
+  def Start( self ):
     self._request_data = BuildRequestData()
     if self._extra_data:
       self._request_data.update( self._extra_data )
     self._request_data.update( {
       'command_arguments': self._arguments
     } )
-    self._response = self.PostDataToHandler( self._request_data,
-                                             'run_completer_command',
-                                             display_message = not silent )
+    self._response_future = self.PostDataToHandlerAsync(
+      self._request_data,
+      'run_completer_command' )
+
+
+  def Done( self ):
+    return bool( self._response_future ) and self._response_future.done()
 
 
   def Response( self ):
+    if self._response is None and self._response_future is not None:
+      # Block
+      self._response = self.HandleFuture( self._response_future,
+                                          display_message = not self._silent )
+
     return self._response
 
 
-  def RunPostCommandActionsIfNeeded( self, modifiers ):
-    if not self.Done() or self._response is None:
+  def RunPostCommandActionsIfNeeded( self,
+                                     modifiers,
+                                     buffer_command = DEFAULT_BUFFER_COMMAND ):
+
+    # This is a blocking call if not Done()
+    self.Response()
+
+    if self._response is None:
+      # An exception was raised and handled.
       return
 
     # If not a dictionary or a list, the response is necessarily a
@@ -78,7 +94,7 @@ class CommandRequest( BaseRequest ):
     # The only other type of response we understand is GoTo, and that is the
     # only one that we can't detect just by inspecting the response (it should
     # either be a single location or a list)
-    return self._HandleGotoResponse( modifiers )
+    return self._HandleGotoResponse( buffer_command, modifiers )
 
 
   def StringResponse( self ):
@@ -88,8 +104,9 @@ class CommandRequest( BaseRequest ):
     #
     # The supportable public API is basically any text-only response. All other
     # response types are returned as empty strings
-    if not self.Done():
-      raise RuntimeError( "Response is not ready" )
+
+    # This is a blocking call if not Done()
+    self.Response()
 
     # Completer threw an error ?
     if self._response is None:
@@ -112,7 +129,7 @@ class CommandRequest( BaseRequest ):
     return ""
 
 
-  def _HandleGotoResponse( self, modifiers ):
+  def _HandleGotoResponse( self, buffer_command, modifiers ):
     if isinstance( self._response, list ):
       vimsupport.SetQuickFixList(
         [ _BuildQfListItem( x ) for x in self._response ] )
@@ -122,7 +139,7 @@ class CommandRequest( BaseRequest ):
                                  self._response[ 'line_num' ],
                                  self._response[ 'column_num' ],
                                  modifiers,
-                                 self._buffer_command )
+                                 buffer_command )
 
 
   def _HandleFixitResponse( self ):
@@ -176,21 +193,32 @@ class CommandRequest( BaseRequest ):
     vimsupport.WriteToPreviewWindow( self._response[ 'detailed_info' ] )
 
 
+def SendCommandRequestAsync( arguments, extra_data = None, silent = True ):
+  request = CommandRequest( arguments,
+                            extra_data = extra_data,
+                            silent = silent )
+  request.Start()
+  # Don't block
+  return request
+
+
 def SendCommandRequest( arguments,
                         modifiers,
-                        buffer_command,
+                        buffer_command = DEFAULT_BUFFER_COMMAND,
                         extra_data = None ):
-  request = CommandRequest( arguments, buffer_command, extra_data )
-  # This is a blocking call.
-  request.Start()
-  request.RunPostCommandActionsIfNeeded( modifiers )
+  request = SendCommandRequestAsync( arguments,
+                                     extra_data = extra_data,
+                                     silent = False )
+  # Block here to get the response
+  request.RunPostCommandActionsIfNeeded( modifiers, buffer_command )
   return request.Response()
 
 
 def GetCommandResponse( arguments, extra_data = None ):
-  request = CommandRequest( arguments, "", extra_data )
-  # This is a blocking call.
-  request.Start( silent = True )
+  request = SendCommandRequestAsync( arguments,
+                                     extra_data = extra_data,
+                                     silent = True )
+  # Block here to get the response
   return request.StringResponse()
 
 

python/ycm/youcompleteme.py

@@ -32,7 +32,9 @@ from ycm import syntax_parse
 from ycm.client.ycmd_keepalive import YcmdKeepalive
 from ycm.client.base_request import BaseRequest, BuildRequestData
 from ycm.client.completer_available_request import SendCompleterAvailableRequest
-from ycm.client.command_request import SendCommandRequest, GetCommandResponse
+from ycm.client.command_request import ( SendCommandRequest,
+                                         SendCommandRequestAsync,
+                                         GetCommandResponse )
 from ycm.client.completion_request import CompletionRequest
 from ycm.client.signature_help_request import ( SignatureHelpRequest,
                                                 SigHelpAvailableByFileType )
@@ -94,23 +96,12 @@ HANDLE_FLAG_INHERIT = 0x00000001
 
 class YouCompleteMe:
   def __init__( self ):
-    self._available_completers = {}
-    self._user_options = None
-    self._user_notified_about_crash = False
-    self._omnicomp = None
-    self._buffers = None
-    self._latest_completion_request = None
-    self._latest_signature_help_request = None
-    self._signature_help_available_requests = SigHelpAvailableByFileType()
-    self._signature_help_state = signature_help.SignatureHelpState()
     self._logger = logging.getLogger( 'ycm' )
     self._client_logfile = None
     self._server_stdout = None
     self._server_stderr = None
     self._server_popen = None
-    self._filetypes_with_keywords_loaded = set()
     self._ycmd_keepalive = YcmdKeepalive()
-    self._server_is_ready_with_cache = False
     self._SetUpLogging()
     self._SetUpServer()
     self._ycmd_keepalive.Start()
@@ -123,6 +114,12 @@ class YouCompleteMe:
     self._server_is_ready_with_cache = False
     self._message_poll_requests = {}
 
+    self._latest_completion_request = None
+    self._latest_signature_help_request = None
+    self._signature_help_available_requests = SigHelpAvailableByFileType()
+    self._latest_command_reqeust = None
+
+    self._signature_help_state = signature_help.SignatureHelpState()
     self._user_options = base.GetUserOptions()
     self._omnicomp = OmniCompleter( self._user_options )
     self._buffers = BufferDict( self._user_options )
@@ -411,10 +408,11 @@ class YouCompleteMe:
       has_range,
       start_line,
       end_line )
-    return SendCommandRequest( final_arguments,
-                               modifiers,
-                               self._user_options[ 'goto_buffer_command' ],
-                               extra_data )
+    return SendCommandRequest(
+      final_arguments,
+      modifiers,
+      self._user_options[ 'goto_buffer_command' ],
+      extra_data )
 
 
   def GetCommandResponse( self, arguments ):
@@ -426,10 +424,24 @@ class YouCompleteMe:
     return GetCommandResponse( final_arguments, extra_data )
 
 
+  def SendCommandRequestAsync( self, arguments ):
+    final_arguments, extra_data = self._GetCommandRequestArguments(
+      arguments,
+      False,
+      0,
+      0 )
+    self._latest_command_reqeust = SendCommandRequestAsync( final_arguments,
+                                                            extra_data )
+
+
+  def GetCommandRequest( self ):
+    return self._latest_command_reqeust
+
 
   def GetDefinedSubcommands( self ):
-    subcommands = BaseRequest().PostDataToHandler( BuildRequestData(),
-                                                   'defined_subcommands' )
+    request = BaseRequest()
+    subcommands = request.PostDataToHandler( BuildRequestData(),
+                                             'defined_subcommands' )
     return subcommands if subcommands else []
 
 

run_tests.py

@@ -1,4 +1,4 @@
-#!/usr/bin/env python
+#!/usr/bin/env python3
 
 import argparse
 import glob

test/hover.test.vim

@@ -1,3 +1,29 @@
+function! s:WaitForCommandRequestComplete()
+  call WaitForAssert( { ->
+        \ assert_true( py3eval(
+        \     'ycm_state.GetCommandRequest() is not None and '
+        \   . 'ycm_state.GetCommandRequest().Done()' ) )
+        \ } )
+
+  call WaitForAssert( { ->
+        \ assert_equal( -1,
+        \               youcompleteme#Test_GetPollers().command.id )
+        \ } )
+endfunction
+
+function! s:CheckNoCommandRequest()
+  call WaitForAssert( { ->
+        \ assert_true( py3eval(
+        \     'ycm_state.GetCommandRequest() is None or '
+        \   . 'ycm_state.GetCommandRequest().Done()' ) )
+        \ } )
+
+  call WaitForAssert( { ->
+        \ assert_equal( -1,
+        \               youcompleteme#Test_GetPollers().command.id )
+        \ } )
+endfunction
+
 function! s:CheckPopupVisible( row, col, text, syntax )
   " Takes a buffer position, converts it to a screen position and checks the
   " popup found at that location
@@ -11,14 +37,17 @@ function! s:CheckPopupVisibleScreenPos( loc, text, syntax )
   " has 'text' (a list of lines) and 'syntax' the &syntax setting
   " popup found at that location
   redraw
+  call s:WaitForCommandRequestComplete()
+  call WaitForAssert( { ->
+        \   assert_notequal( 0,
+        \                    popup_locate( a:loc.row, a:loc.col ),
+        \                    'Locate popup at ('
+        \                    . a:loc.row
+        \                    . ','
+        \                    . a:loc.col
+        \                    . ')' )
+       \ } )
   let popup = popup_locate( a:loc.row, a:loc.col )
-  call assert_notequal( 0,
-                      \ popup,
-                      \ 'Locate popup at ('
-                      \ . a:loc.row
-                      \ . ','
-                      \ . a:loc.col
-                      \ . ')' )
   if a:text isnot v:none
     call assert_equal( a:text,
                      \ getbufline( winbufnr( popup ), 1, '$' ) )
@@ -26,21 +55,29 @@ function! s:CheckPopupVisibleScreenPos( loc, text, syntax )
   call assert_equal( a:syntax, getbufvar( winbufnr( popup ), '&syntax' ) )
 endfunction
 
-function! s:CheckPopupNotVisible( row, col )
+function! s:CheckPopupNotVisible( row, col, with_request=v:true )
   " Takes a buffer position and ensures there is no popup visible at that
   " position. Like CheckPopupVisible, the position must be valid (i.e. there
   " must be buffer text at that position). Otherwise, you need to pass the
   " _screen_ position to CheckPopupNotVisibleScreenPos
   redraw
   let loc = screenpos( win_getid(), a:row, a:col )
-  return s:CheckPopupNotVisibleScreenPos( loc )
+  return s:CheckPopupNotVisibleScreenPos( loc, a:with_request )
 endfunction
 
-function! s:CheckPopupNotVisibleScreenPos( loc )
+function! s:CheckPopupNotVisibleScreenPos( loc, with_request=v:true )
   " Takes a position dict like the one returned by screenpos() and verifies it
   " does not have a popup drawn on it.
   redraw
-  call assert_equal( 0, popup_locate( a:loc.row, a:loc.col ) )
+  if a:with_request
+    call s:WaitForCommandRequestComplete()
+  else
+    call s:CheckNoCommandRequest()
+  endif
+  call WaitForAssert( { ->
+        \   assert_equal( 0,
+        \                 popup_locate( a:loc.row, a:loc.col ) )
+        \ } )
 endfunction
 
 let s:python_oneline = {
@@ -69,6 +106,8 @@ endfunction
 
 function! TearDown()
   let g:ycm_auto_hover='CursorHold'
+
+  call assert_equal( -1, youcompleteme#Test_GetPollers().command.id )
 endfunction
 
 function! Test_Hover_Uses_GetDoc()
@@ -135,7 +174,7 @@ EOPYTHON
 
   call setpos( '.', [ 0, 12, 3 ] )
   normal \D
-  call s:CheckPopupNotVisible( 11, 4 )
+  call s:CheckPopupNotVisible( 11, 4, v:false )
 
   call popup_clear()
   %bwipe!
@@ -154,8 +193,8 @@ EOPYTHON
 
   call assert_equal( { 'command': 'GetType', 'syntax': 'python' }, b:ycm_hover )
 
-  call s:CheckPopupNotVisible( 2, 1 )
-  call s:CheckPopupNotVisible( 2, 2 )
+  call s:CheckPopupNotVisible( 2, 1, v:none )
+  call s:CheckPopupNotVisible( 2, 2, v:none )
 
   " some doc - autocommand
   call setpos( '.', [ 0, 12, 3 ] )
@@ -185,10 +224,12 @@ function! Test_Hover_NonNative()
   setfiletype NoASupportedFileType
   let messages_before = execute( 'messages' )
   doautocmd CursorHold
+  call s:CheckNoCommandRequest()
   call assert_false( exists( 'b:ycm_hover' ) )
   call assert_equal( messages_before, execute( 'messages' ) )
 
   normal \D
+  call s:CheckNoCommandRequest()
   call assert_false( exists( 'b:ycm_hover' ) )
   call assert_equal( messages_before, execute( 'messages' ) )
 
@@ -205,6 +246,7 @@ function! Test_Hover_Disabled_NonNative()
   setfiletype NoASupportedFileType
   let messages_before = execute( 'messages' )
   silent doautocmd CursorHold
+  call s:CheckNoCommandRequest()
   call assert_false( exists( 'b:ycm_hover' ) )
   call assert_equal( messages_before, execute( 'messages' ) )
 
@@ -225,7 +267,7 @@ function! Test_AutoHover_Disabled()
 
   call setpos( '.', [ 0, 12, 3 ] )
   silent doautocmd CursorHold
-  call s:CheckPopupNotVisible( 11, 4 )
+  call s:CheckPopupNotVisible( 11, 4, v:false )
   call assert_equal( messages_before, execute( 'messages' ) )
 
   " Manual hover is still supported
@@ -236,7 +278,7 @@ function! Test_AutoHover_Disabled()
 
   " Manual close hover is still supported
   normal \D
-  call s:CheckPopupNotVisible( 11, 4 )
+  call s:CheckPopupNotVisible( 11, 4, v:false )
   call assert_equal( messages_before, execute( 'messages' ) )
 
   call popup_clear()
@@ -270,10 +312,6 @@ function! Test_Hover_MoveCursor()
   call feedkeys( "b\\D", 'xt' )
   call s:CheckPopupVisible( 11, 3, s:python_oneline.GetDoc, '' )
 
-  " line
-  call feedkeys( "ji\<Esc>", 'xt' )
-  call s:CheckPopupNotVisible( 11, 3 )
-
   call test_override( 'ALL', 0 )
 
   call popup_clear()
@@ -295,11 +333,11 @@ function! Test_Hover_Dismiss()
 
   " Dismiss
   normal \D
-  call s:CheckPopupNotVisible( 11, 3 )
+  call s:CheckPopupNotVisible( 11, 3, v:false )
 
   " Make sure it doesn't come back
   doautocmd CursorHold
-  call s:CheckPopupNotVisible( 11, 3 )
+  call s:CheckPopupNotVisible( 11, 3, v:false )
 
   " Move the cursor (again this is tricky). I couldn't find any tests in vim's
   " own code that trigger CursorMoved, so we just cheat. (for the record, just
@@ -336,7 +374,7 @@ function! Test_Hover_Custom_Syntax()
                                    \ 'cpp' )
 
   normal \D
-  call s:CheckPopupNotVisibleScreenPos( { 'row': 7, 'col': 9 } )
+  call s:CheckPopupNotVisibleScreenPos( { 'row': 7, 'col': 9 }, v:false )
 
   call popup_clear()
   %bwipe!
@@ -386,8 +424,8 @@ function! Test_Long_Single_Line()
   call s:CheckPopupVisible( 36, 1, v:none, '' )
   call s:CheckPopupVisible( 36, &columns, v:none, '' )
 
-  call s:CheckPopupNotVisible( 37, 1 )
-  call s:CheckPopupNotVisible( 37, &columns )
+  call s:CheckPopupNotVisible( 37, 1, v:false )
+  call s:CheckPopupNotVisible( 37, &columns, v:false )
 
   " Also wrap is ON so it should cover at least 2 lines + 2 for the header/empty
   " line
@@ -410,16 +448,16 @@ function! Test_Long_Wrapped()
   call s:CheckPopupVisible( 37, 1, v:none, '' )
   call s:CheckPopupVisible( 37, &columns, v:none, '' )
 
-  call s:CheckPopupNotVisible( 38, 1 )
-  call s:CheckPopupNotVisible( 38, &columns )
+  call s:CheckPopupNotVisible( 38, 1, v:false )
+  call s:CheckPopupNotVisible( 38, &columns, v:false )
 
   " Also, wrap is off, so it should be _exactly_ 9 lines + 2 for the signature
   " and the empty line
   call s:CheckPopupVisible( 27, 1, v:none, '' )
   call s:CheckPopupVisible( 27, &columns, v:none, '' )
 
-  call s:CheckPopupNotVisible( 26, 1 )
-  call s:CheckPopupNotVisible( 26, &columns )
+  call s:CheckPopupNotVisible( 26, 1, v:false )
+  call s:CheckPopupNotVisible( 26, &columns, v:false )
 
   call popup_clear()
   %bwipe!

test/lib/run_test.vim

@@ -146,15 +146,19 @@ func RunTheTest(test)
     let s:testid_filesafe = g:testpath . '_' . test_filesafe
 
     au VimLeavePre * call EarlyExit(s:test)
+    call ch_log( 'StartTest: ' . a:test )
     exe 'call ' . a:test
+    call ch_log( 'EndTest: ' . a:test )
     au! VimLeavePre
   catch /^\cskipped/
+    call ch_log( 'Skipped: ' . a:test )
     call add(s:messages, '    Skipped')
     call add(s:skipped,
           \ 'SKIPPED ' . a:test
           \ . ': '
           \ . substitute(v:exception, '^\S*\s\+', '',  ''))
   catch
+    call ch_log( 'Catch: ' . a:test )
     call add(v:errors,
           \ 'Caught exception in ' . a:test
           \ . ': '