Auto merge of #1760 - micbou:ycm-toggle-logs, r=Valloric

Introducing :YcmToggleLogs command

Two approaches were proposed in PR #1753:
- open the stdout and stderr logfiles in Vim windows or close them if already opened: `:YcmToggleLogs`;
- open one of the logfiles in the preview window by specifying it as an argument in the command: `:YcmShowLog <stdout|stderr>`.

This PR merges both approaches by adding an optional argument (`Stdout` or `Stderr`) to the first approach. When no argument is given, both logfiles are opened (or closed if already opened).

With this approach, we cannot use the preview window because only one such window is allowed by Vim. So, we simulate it by adding properties specific to the preview window (horizontal split, height, etc.)

Since they are multiple ways to open a file in Vim, I added a generic function `OpenFilename` for this. It makes easy to customize the way logfiles are opened and could be useful for new features.

Tests were a pain to add and I am not sure of the way I implemented them. If someone could review them. There is some refactoring of the Vim mock.

I updated the documentation and the contribution guidelines. I added a new instruction when creating an issue: adding the output of the `:YcmDebugInfo` command. We often ask it in the issues.

I suggest fetching the `ycm-toggle-logs` branch of my repository to test yourself this command.

<!-- Reviewable:start -->
[<img src="https://reviewable.io/review_button.png" height=40 alt="Review on Reviewable"/>](https://reviewable.io/reviews/valloric/youcompleteme/1760)
<!-- Reviewable:end -->

CONTRIBUTING.md

@@ -51,17 +51,17 @@ Here are the things you should do when creating an issue:
    let g:ycm_server_log_level = 'debug'
    ```
 
-   Run `:YcmDebugInfo` in vim to see what temporary files (listed under "Server
+   Run `:YcmToggleLogs stderr` in vim to open the logfile. Attach the contents
-   logfiles") the debug output streams are written to. Attach the debug output
+   of this file to your issue.
-   stream to your issue.
+3. Add the output of the `:YcmDebugInfo` command.
-3. **Create a test case for your issue**. This is critical. Don't talk about how
+4. **Create a test case for your issue**. This is critical. Don't talk about how
    "when I have X in my file" or similar, _create a file with X in it_ and put
    the contents inside code blocks in your issue description. Try to make this
    test file _as small as possible_. Don't just paste a huge, 500 line source
    file you were editing and present that as a test. _Minimize_ the file so that
    the problem is reproduced with the smallest possible amount of test data.
-4. **Include your OS and OS version.**
+5. **Include your OS and OS version.**
-5. **Include the output of `vim --version`.**
+6. **Include the output of `vim --version`.**
 
 
 Creating good pull requests

README.md

@@ -871,6 +871,14 @@ This will print out various debug information for the current file. Useful to
 see what compile commands will be used for the file if you're using the semantic
 completion engine.
 
+### The `:YcmToggleLogs` command
+
+This command automatically opens in windows the stdout and stderr logfiles
+written by the `ycmd` server. If one or both logfiles are already opened, they
+are automatically closed. `stderr` or `stdout` can be specified as an argument
+of this command to only open the corresponding logfile instead of both. If this
+logfile is already opened, it will be closed. Only for debugging purpose.
+
 ### The `:YcmCompleter` command
 
 This command can be used to invoke completer-specific commands.  If the first
@@ -1986,8 +1994,10 @@ the message log if it encounters problems. It's likely you misconfigured
 something and YCM is complaining about it.
 
 Also, you may want to run the `:YcmDebugInfo` command; it will make YCM spew out
-various debugging information, including the compile flags for the file if the
+various debugging information, including the `ycmd` logfile paths and the
-file is a C-family language file and you have compiled in Clang support.
+compile flags for the current file if the file is a C-family language file and
+you have compiled in Clang support. Logfiles can be automatically opened in the
+editor using the `:YcmToggleLogs` command.
 
 ### Sometimes it takes much longer to get semantic completions than normal
 

autoload/youcompleteme.vim

@@ -310,6 +310,8 @@ function! s:SetUpCommands()
   command! YcmRestartServer call s:RestartServer()
   command! YcmShowDetailedDiagnostic call s:ShowDetailedDiagnostic()
   command! YcmDebugInfo call s:DebugInfo()
+  command! -nargs=? -complete=custom,youcompleteme#LogsComplete
+    \ YcmToggleLogs call s:ToggleLogs(<f-args>)
   command! -nargs=* -complete=custom,youcompleteme#SubCommandsComplete
     \ YcmCompleter call s:CompleterCommand(<f-args>)
   command! YcmForceCompileAndDiagnostics call s:ForceCompileAndDiagnostics()
@@ -763,6 +765,14 @@ function! s:DebugInfo()
 endfunction
 
 
+function! s:ToggleLogs(...)
+  let stderr = a:0 == 0 || a:1 !=? 'stdout'
+  let stdout = a:0 == 0 || a:1 !=? 'stderr'
+  py ycm_state.ToggleLogs( stdout = vimsupport.GetBoolValue( 'l:stdout' ),
+                         \ stderr = vimsupport.GetBoolValue( 'l:stderr' ) )
+endfunction
+
+
 function! s:CompleterCommand(...)
   " CompleterCommand will call the OnUserCommand function of a completer.
   " If the first arguments is of the form "ft=..." it can be used to specify the
@@ -796,6 +806,11 @@ function! youcompleteme#OpenGoToList()
 endfunction
 
 
+function! youcompleteme#LogsComplete( arglead, cmdline, cursorpos )
+  return "stdout\nstderr"
+endfunction
+
+
 function! youcompleteme#SubCommandsComplete( arglead, cmdline, cursorpos )
   return join( pyeval( 'ycm_state.GetDefinedSubcommands()' ),
     \ "\n")

doc/youcompleteme.txt

@@ -36,7 +36,8 @@ Contents ~
   3. The |:YcmDiags| command
   4. The |:YcmShowDetailedDiagnostic| command
   5. The |:YcmDebugInfo| command
-  6. The |:YcmCompleter| command
+  6. The |:YcmToggleLogs| command
+  7. The |:YcmCompleter| command
  7. YcmCompleter subcommands           |youcompleteme-ycmcompleter-subcommands|
   1. The |GoToInclude| subcommand
   2. The |GoToDeclaration| subcommand
@@ -1081,6 +1082,15 @@ This will print out various debug information for the current file. Useful to
 see what compile commands will be used for the file if you're using the
 semantic completion engine.
 
+-------------------------------------------------------------------------------
+The *:YcmToggleLogs* command
+
+This command automatically opens in windows the stdout and stderr logfiles
+written by the 'ycmd' server. If one or both logfiles are already opened, they
+are automatically closed. 'stderr' or 'stdout' can be specified as an argument
+of this command to only open the corresponding logfile instead of both. If this
+logfile is already opened, it will be closed. Only for debugging purpose.
+
 -------------------------------------------------------------------------------
 The *:YcmCompleter* command
 
@@ -2164,8 +2174,10 @@ to the message log if it encounters problems. It's likely you misconfigured
 something and YCM is complaining about it.
 
 Also, you may want to run the |:YcmDebugInfo| command; it will make YCM spew
-out various debugging information, including the compile flags for the file if
+out various debugging information, including the 'ycmd' logfile paths and the
-the file is a C-family language file and you have compiled in Clang support.
+compile flags for the current file if the file is a C-family language file and
+you have compiled in Clang support. Logfiles can be automatically opened in the
+editor using the |:YcmToggleLogs| command.
 
 -------------------------------------------------------------------------------
 *youcompleteme-sometimes-it-takes-much-longer-to-get-semantic-completions-than-normal*

python/ycm/test_utils.py

@@ -18,18 +18,77 @@
 # along with YouCompleteMe.  If not, see <http://www.gnu.org/licenses/>.
 
 from mock import MagicMock
+import re
 import sys
 
+
+BUFNR_REGEX = re.compile( r"^bufnr\('(.+)', ([0-9]+)\)$" )
+BUFWINNR_REGEX = re.compile( r"^bufwinnr\(([0-9]+)\)$" )
+BWIPEOUT_REGEX = re.compile( r"^(?:silent! )bwipeout!? ([0-9]+)$" )
+
 # One-and only instance of mocked Vim object. The first 'import vim' that is
 # executed binds the vim module to the instance of MagicMock that is created,
-# and subsquent assignments to sys.modules[ 'vim' ] don't retrospectively update
+# and subsquent assignments to sys.modules[ 'vim' ] don't retrospectively
-# them. The result is that while running the tests, we must assign only one
+# update them. The result is that while running the tests, we must assign only
-# instance of MagicMock to sys.modules[ 'vim' ] and always return it.
+# one instance of MagicMock to sys.modules[ 'vim' ] and always return it.
 #
 # More explanation is available:
 # https://github.com/Valloric/YouCompleteMe/pull/1694
 VIM_MOCK = MagicMock()
 
+
+def MockGetBufferNumber( buffer_filename ):
+  for buffer in VIM_MOCK.buffers:
+    if buffer[ 'filename' ] == buffer_filename:
+      return buffer[ 'number' ]
+  return -1
+
+
+def MockGetBufferWindowNumber( buffer_number ):
+  for buffer in VIM_MOCK.buffers:
+    if buffer[ 'number' ] == buffer_number and 'window' in buffer:
+      return buffer[ 'window' ]
+  return -1
+
+
+def MockVimEval( value ):
+  if value == "g:ycm_min_num_of_chars_for_completion":
+    return 0
+  if value == "g:ycm_path_to_python_interpreter":
+    return ''
+  if value == "tempname()":
+    return '_TEMP_FILE_'
+  if value == "&previewheight":
+    # Default value from Vim
+    return 12
+
+  match = BUFNR_REGEX.search( value )
+  if match:
+    return MockGetBufferNumber( match.group( 1 ) )
+
+  match = BUFWINNR_REGEX.search( value )
+  if match:
+    return MockGetBufferWindowNumber( int( match.group( 1 ) ) )
+
+  raise ValueError( 'Unexpected evaluation: ' + value )
+
+
+def MockWipeoutBuffer( buffer_number ):
+  buffers = VIM_MOCK.buffers
+
+  for index, buffer in enumerate( buffers ):
+    if buffer[ 'number' ] == buffer_number:
+      return buffers.pop( index )
+
+
+def MockVimCommand( command ):
+  match = BWIPEOUT_REGEX.search( command )
+  if match:
+    return MockWipeoutBuffer( int( match.group( 1 ) ) )
+
+  raise RuntimeError( 'Unexpected command: ' + command )
+
+
 def MockVimModule():
   """The 'vim' module is something that is only present when running inside the
   Vim Python interpreter, so we replace it with a MagicMock for tests. If you
@@ -52,12 +111,8 @@ def MockVimModule():
   Failure to use this approach may lead to unexpected failures in other
   tests."""
 
-  def VimEval( value ):
+  VIM_MOCK.buffers = {}
-    if value == "g:ycm_min_num_of_chars_for_completion":
+  VIM_MOCK.eval = MagicMock( side_effect = MockVimEval )
-      return 0
-    return ''
-
-  VIM_MOCK.eval = MagicMock( side_effect = VimEval )
   sys.modules[ 'vim' ] = VIM_MOCK
 
   return VIM_MOCK

python/ycm/tests/vimsupport_test.py

@@ -17,12 +17,14 @@
 # You should have received a copy of the GNU General Public License
 # along with YouCompleteMe.  If not, see <http://www.gnu.org/licenses/>.
 
-from ycm.test_utils import MockVimModule
+from ycm.test_utils import MockVimModule, MockVimCommand
 MockVimModule()
 
 from ycm import vimsupport
 from nose.tools import eq_
+from hamcrest import assert_that, calling, raises, none
 from mock import MagicMock, call, patch
+import os
 
 
 def ReplaceChunk_SingleLine_Repl_1_test():
@@ -582,17 +584,9 @@ def _BuildChunk( start_line, start_column, end_line, end_column,
   }
 
 
-def _Mock_tempname( arg ):
-  if arg == 'tempname()':
-    return '_TEMP_FILE_'
-
-  raise ValueError( 'Unexpected evaluation: ' + arg )
-
-
-@patch( 'vim.eval', side_effect=_Mock_tempname )
 @patch( 'vim.command' )
 @patch( 'vim.current' )
-def WriteToPreviewWindow_test( vim_current, vim_command, vim_eval ):
+def WriteToPreviewWindow_test( vim_current, vim_command ):
   vim_current.window.options.__getitem__ = MagicMock( return_value = True )
 
   vimsupport.WriteToPreviewWindow( "test" )
@@ -615,9 +609,8 @@ def WriteToPreviewWindow_test( vim_current, vim_command, vim_eval ):
   ], any_order = True )
 
 
-@patch( 'vim.eval', side_effect=_Mock_tempname )
 @patch( 'vim.current' )
-def WriteToPreviewWindow_MultiLine_test( vim_current, vim_eval ):
+def WriteToPreviewWindow_MultiLine_test( vim_current ):
   vim_current.window.options.__getitem__ = MagicMock( return_value = True )
   vimsupport.WriteToPreviewWindow( "test\ntest2" )
 
@@ -625,10 +618,9 @@ def WriteToPreviewWindow_MultiLine_test( vim_current, vim_eval ):
       slice( None, None, None ), [ 'test', 'test2' ] )
 
 
-@patch( 'vim.eval', side_effect=_Mock_tempname )
 @patch( 'vim.command' )
 @patch( 'vim.current' )
-def WriteToPreviewWindow_JumpFail_test( vim_current, vim_command, vim_eval ):
+def WriteToPreviewWindow_JumpFail_test( vim_current, vim_command ):
   vim_current.window.options.__getitem__ = MagicMock( return_value = False )
 
   vimsupport.WriteToPreviewWindow( "test" )
@@ -644,12 +636,9 @@ def WriteToPreviewWindow_JumpFail_test( vim_current, vim_command, vim_eval ):
   vim_current.buffer.options.__setitem__.assert_not_called()
 
 
-@patch( 'vim.eval', side_effect=_Mock_tempname )
 @patch( 'vim.command' )
 @patch( 'vim.current' )
-def WriteToPreviewWindow_JumpFail_MultiLine_test( vim_current,
+def WriteToPreviewWindow_JumpFail_MultiLine_test( vim_current, vim_command ):
-                                                  vim_command,
-                                                  vim_eval ):
 
   vim_current.window.options.__getitem__ = MagicMock( return_value = False )
 
@@ -665,3 +654,94 @@ def WriteToPreviewWindow_JumpFail_MultiLine_test( vim_current,
 
   vim_current.buffer.__setitem__.assert_not_called()
   vim_current.buffer.options.__setitem__.assert_not_called()
+
+
+def CheckFilename_test():
+  assert_that(
+    calling( vimsupport.CheckFilename ).with_args( None ),
+    raises( RuntimeError, "'None' is not a valid filename" )
+  )
+
+  assert_that(
+    calling( vimsupport.CheckFilename ).with_args( 'nonexistent_file' ),
+    raises( RuntimeError,
+            "filename 'nonexistent_file' cannot be opened. "
+            "\[Errno 2\] No such file or directory: 'nonexistent_file'" )
+  )
+
+  assert_that( vimsupport.CheckFilename( __file__ ), none() )
+
+
+def BufferIsVisibleForFilename_test():
+  buffers = [
+    {
+      'number': 1,
+      'filename': os.path.realpath( 'visible_filename' ),
+      'window': 1
+    },
+    {
+      'number': 2,
+      'filename': os.path.realpath( 'hidden_filename' ),
+    }
+  ]
+
+  with patch( 'vim.buffers', buffers ):
+    eq_( vimsupport.BufferIsVisibleForFilename( 'visible_filename' ), True )
+    eq_( vimsupport.BufferIsVisibleForFilename( 'hidden_filename' ), False )
+    eq_( vimsupport.BufferIsVisibleForFilename( 'another_filename' ), False )
+
+
+@patch( 'vim.command', side_effect = MockVimCommand )
+def CloseBuffersForFilename_test( vim_command ):
+  buffers = [
+    {
+      'number': 2,
+      'filename': os.path.realpath( 'some_filename' ),
+    },
+    {
+      'number': 5,
+      'filename': os.path.realpath( 'some_filename' ),
+    },
+    {
+      'number': 1,
+      'filename': os.path.realpath( 'another_filename' )
+    }
+  ]
+
+  with patch( 'vim.buffers', buffers ):
+    vimsupport.CloseBuffersForFilename( 'some_filename' )
+
+  vim_command.assert_has_calls( [
+    call( 'silent! bwipeout! 2' ),
+    call( 'silent! bwipeout! 5' )
+  ], any_order = True )
+
+
+@patch( 'vim.command' )
+@patch( 'vim.current' )
+def OpenFilename_test( vim_current, vim_command ):
+  # Options used to open a logfile
+  options = {
+    'size': vimsupport.GetIntValue( '&previewheight' ),
+    'fix': True,
+    'watch': True,
+    'position': 'end'
+  }
+
+  vimsupport.OpenFilename( __file__, options )
+
+  vim_command.assert_has_calls( [
+    call( 'silent! 12split {0}'.format( __file__ ) ),
+    call( "exec "
+          "'au BufEnter <buffer> :silent! checktime {0}'".format( __file__ ) ),
+    call( 'silent! normal G zz' ),
+    call( 'silent! wincmd p' )
+  ] )
+
+  vim_current.buffer.options.__setitem__.assert_has_calls( [
+    call( 'autoread', True ),
+  ] )
+
+  vim_current.window.options.__setitem__.assert_has_calls( [
+    call( 'winfixheight', True )
+  ] )

python/ycm/vimsupport.py

@@ -331,9 +331,9 @@ def TryJumpLocationInOpenedTab( filename, line, column ):
   return False
 
 
-# Maps User jump command to vim jump command
+# Maps User command to vim command
-def GetVimJumpCommand( user_command ):
+def GetVimCommand( user_command, default = 'edit' ):
-  vim_command = BUFFER_COMMAND_MAP.get( user_command, 'edit' )
+  vim_command = BUFFER_COMMAND_MAP.get( user_command, default )
   if vim_command == 'edit' and not BufferIsUsable( vim.current.buffer ):
     vim_command = 'split'
   return vim_command
@@ -358,7 +358,7 @@ def JumpToLocation( filename, line, column ):
         return
       user_command = 'new-tab'
 
-    vim_command = GetVimJumpCommand( user_command )
+    vim_command = GetVimCommand( user_command )
     try:
       vim.command( 'keepjumps {0} {1}'.format( vim_command,
                                                EscapedFilepath( filename ) ) )
@@ -610,6 +610,11 @@ def JumpToPreviousWindow():
   vim.command( 'silent! wincmd p' )
 
 
+def JumpToTab( tab_number ):
+  """Jump to Vim tab with corresponding number """
+  vim.command( 'silent! tabn {0}'.format( tab_number ) )
+
+
 def OpenFileInPreviewWindow( filename ):
   """ Open the supplied filename in the preview window """
   vim.command( 'silent! pedit! ' + filename )
@@ -653,3 +658,88 @@ def WriteToPreviewWindow( message ):
     # the information we have. The only remaining option is to echo to the
     # status area.
     EchoText( message )
+
+
+def CheckFilename( filename ):
+  """Check if filename is openable."""
+  try:
+    open( filename ).close()
+  except TypeError:
+    raise RuntimeError( "'{0}' is not a valid filename".format( filename ) )
+  except IOError as error:
+    raise RuntimeError(
+      "filename '{0}' cannot be opened. {1}".format( filename, error ) )
+
+
+def BufferIsVisibleForFilename( filename ):
+  """Check if a buffer exists for a specific file."""
+  buffer_number = GetBufferNumberForFilename( filename, False )
+  return BufferIsVisible( buffer_number )
+
+
+def CloseBuffersForFilename( filename ):
+  """Close all buffers for a specific file."""
+  buffer_number = GetBufferNumberForFilename( filename, False )
+  while buffer_number is not -1:
+    vim.command( 'silent! bwipeout! {0}'.format( buffer_number ) )
+    new_buffer_number = GetBufferNumberForFilename( filename, False )
+    if buffer_number == new_buffer_number:
+      raise RuntimeError( "Buffer {0} for filename '{1}' should already be "
+                          "wiped out.".format( buffer_number, filename ) )
+    buffer_number = new_buffer_number
+
+
+def OpenFilename( filename, options = {} ):
+  """Open a file in Vim. Following options are available:
+  - command: specify which Vim command is used to open the file. Choices
+  are same-buffer, horizontal-split, vertical-split, and new-tab (default:
+  horizontal-split);
+  - size: set the height of the window for a horizontal split or the width for
+  a vertical one (default: '');
+  - fix: set the winfixheight option for a horizontal split or winfixwidth for
+  a vertical one (default: False). See :h winfix for details;
+  - focus: focus the opened file (default: False);
+  - watch: automatically watch for changes (default: False). This is useful
+  for logs;
+  - position: set the position where the file is opened (default: start).
+  Choices are start and end."""
+
+  # Set the options.
+  command = GetVimCommand( options.get( 'command', 'horizontal-split' ),
+                           'horizontal-split' )
+  size = ( options.get( 'size', '' ) if command in [ 'split', 'vsplit' ] else
+           '' )
+  focus = options.get( 'focus', False )
+  watch = options.get( 'watch', False )
+  position = options.get( 'position', 'start' )
+
+  # There is no command in Vim to return to the previous tab so we need to
+  # remember the current tab if needed.
+  if not focus and command is 'tabedit':
+    previous_tab = GetIntValue( 'tabpagenr()' )
+
+  # Open the file
+  CheckFilename( filename )
+  vim.command( 'silent! {0}{1} {2}'.format( size, command, filename ) )
+
+  if command is 'split':
+    vim.current.window.options[ 'winfixheight' ] = options.get( 'fix', False )
+  if command is 'vsplit':
+    vim.current.window.options[ 'winfixwidth' ] = options.get( 'fix', False )
+
+  if watch:
+    vim.current.buffer.options[ 'autoread' ] = True
+    vim.command( "exec 'au BufEnter <buffer> :silent! checktime {0}'"
+                 .format( filename ) )
+
+  if position is 'end':
+    vim.command( 'silent! normal G zz' )
+
+  # Vim automatically set the focus to the opened file so we need to get the
+  # focus back (if the focus option is disabled) when opening a new tab or
+  # window.
+  if not focus:
+    if command is 'tabedit':
+      JumpToTab( previous_tab )
+    if command in [ 'split', 'vsplit' ]:
+      JumpToPreviousWindow()

python/ycm/youcompleteme.py

@@ -176,6 +176,7 @@ class YouCompleteMe( object ):
 
 
   def RestartServer( self ):
+    self._CloseLogs()
     vimsupport.PostVimMessage( 'Restarting ycmd server...' )
     self._user_notified_about_crash = False
     self._ServerCleanup()
@@ -507,6 +508,47 @@ class YouCompleteMe( object ):
     return debug_info
 
 
+  def _OpenLogs( self, stdout = True, stderr = True ):
+    # Open log files in a horizontal window with the same behavior as the
+    # preview window (same height and winfixheight enabled). Automatically
+    # watch for changes. Set the cursor position at the end of the file.
+    options = {
+      'size': vimsupport.GetIntValue( '&previewheight' ),
+      'fix': True,
+      'watch': True,
+      'position': 'end'
+    }
+
+    if stdout:
+      vimsupport.OpenFilename( self._server_stdout, options )
+    if stderr:
+      vimsupport.OpenFilename( self._server_stderr, options )
+
+
+  def _CloseLogs( self, stdout = True, stderr = True ):
+    if stdout:
+      vimsupport.CloseBuffersForFilename( self._server_stdout )
+    if stderr:
+      vimsupport.CloseBuffersForFilename( self._server_stderr )
+
+
+  def ToggleLogs( self, stdout = True, stderr = True ):
+    if ( stdout and
+         vimsupport.BufferIsVisibleForFilename( self._server_stdout ) or
+         stderr and
+         vimsupport.BufferIsVisibleForFilename( self._server_stderr ) ):
+      return self._CloseLogs( stdout = stdout, stderr = stderr )
+
+    # Close hidden logfile buffers if any to keep a clean state
+    self._CloseLogs( stdout = stdout, stderr = stderr )
+
+    try:
+      self._OpenLogs( stdout = stdout, stderr = stderr )
+    except RuntimeError as error:
+      vimsupport.PostVimMessage( 'YouCompleteMe encountered an error when '
+                                 'opening logs: {0}.'.format( error ) )
+
+
   def CurrentFiletypeCompletionEnabled( self ):
     filetypes = vimsupport.CurrentFiletypes()
     filetype_to_disable = self._user_options[