[VIM-2929]: Adding logging for tracing the keyStack

src/main/java/com/maddyhome/idea/vim/extension/VimExtensionFacade.kt

@@ -9,6 +9,7 @@ package com.maddyhome.idea.vim.extension
 
 import com.intellij.openapi.application.ApplicationManager
 import com.intellij.openapi.components.service
+import com.intellij.openapi.diagnostic.logger
 import com.intellij.openapi.editor.Editor
 import com.maddyhome.idea.vim.KeyHandler
 import com.maddyhome.idea.vim.VimPlugin
@@ -17,7 +18,6 @@ import com.maddyhome.idea.vim.api.ImmutableVimCaret
 import com.maddyhome.idea.vim.api.VimCaret
 import com.maddyhome.idea.vim.api.injector
 import com.maddyhome.idea.vim.command.MappingMode
-import com.maddyhome.idea.vim.state.mode.SelectionType
 import com.maddyhome.idea.vim.common.CommandAlias
 import com.maddyhome.idea.vim.common.CommandAliasHandler
 import com.maddyhome.idea.vim.helper.CommandLineHelper
@@ -26,6 +26,7 @@ import com.maddyhome.idea.vim.helper.vimStateMachine
 import com.maddyhome.idea.vim.key.MappingOwner
 import com.maddyhome.idea.vim.key.OperatorFunction
 import com.maddyhome.idea.vim.newapi.vim
+import com.maddyhome.idea.vim.state.mode.SelectionType
 import com.maddyhome.idea.vim.ui.ModalEntry
 import java.awt.event.KeyEvent
 import javax.swing.KeyStroke
@@ -38,6 +39,9 @@ import javax.swing.KeyStroke
  * @author vlan
  */
 public object VimExtensionFacade {
+
+  private val LOG = logger<VimExtensionFacade>()
+
   /** The 'map' command for mapping keys to handlers defined in extensions. */
   @JvmStatic
   public fun putExtensionHandlerMapping(
@@ -140,22 +144,26 @@ public object VimExtensionFacade {
   public fun inputKeyStroke(editor: Editor): KeyStroke {
     if (editor.vim.vimStateMachine.isDotRepeatInProgress) {
       val input = Extension.consumeKeystroke()
+      LOG.trace("inputKeyStroke: dot repeat in progress. Input: $input")
       return input ?: error("Not enough keystrokes saved: ${Extension.lastExtensionHandler}")
     }
 
     val key: KeyStroke? = if (ApplicationManager.getApplication().isUnitTestMode) {
+      LOG.trace("Unit test mode is active")
       val mappingStack = KeyHandler.getInstance().keyStack
       mappingStack.feedSomeStroke() ?: TestInputModel.getInstance(editor).nextKeyStroke()?.also {
         if (editor.vim.vimStateMachine.isRecording) {
           KeyHandler.getInstance().modalEntryKeys += it
         }
       }
     } else {
+      LOG.trace("Getting char from the modal entry...")
       var ref: KeyStroke? = null
       ModalEntry.activate(editor.vim) { stroke: KeyStroke? ->
         ref = stroke
         false
       }
+      LOG.trace("Got char $ref")
       ref
     }
     val result = key ?: KeyStroke.getKeyStroke(KeyEvent.VK_ESCAPE.toChar())

src/main/java/com/maddyhome/idea/vim/extension/surround/VimSurroundExtension.kt

@@ -8,6 +8,7 @@
 package com.maddyhome.idea.vim.extension.surround
 
 import com.intellij.openapi.application.runWriteAction
+import com.intellij.openapi.diagnostic.logger
 import com.intellij.openapi.editor.Editor
 import com.maddyhome.idea.vim.VimPlugin
 import com.maddyhome.idea.vim.api.ExecutionContext
@@ -249,6 +250,7 @@ internal class VimSurroundExtension : VimExtension {
     override fun execute(editor: VimEditor, context: ExecutionContext, operatorArguments: OperatorArguments) {
       // Deleting surround is just changing the surrounding to "nothing"
       val charFrom = getChar(editor.ij)
+      LOG.debug("DSurroundHandler: charFrom = $charFrom")
       if (charFrom.code == 0) return
 
       runWriteAction { CSurroundHandler.change(editor, context, charFrom, null) }
@@ -282,6 +284,8 @@ internal class VimSurroundExtension : VimExtension {
   }
 }
 
+private val LOG = logger<VimSurroundExtension>()
+
 private const val REGISTER = '"'
 
 private val tagNameAndAttributesCapturePattern = "(\\S+)([^>]*)>".toPattern()
@@ -341,11 +345,13 @@ private fun getOrInputPair(c: Char, editor: Editor): Pair<String, String>? = whe
 private fun getChar(editor: Editor): Char {
   val key = inputKeyStroke(editor)
   val keyChar = key.keyChar
-  return if (keyChar == KeyEvent.CHAR_UNDEFINED || keyChar.code == KeyEvent.VK_ESCAPE) {
+  val res = if (keyChar == KeyEvent.CHAR_UNDEFINED || keyChar.code == KeyEvent.VK_ESCAPE) {
     0.toChar()
   } else {
     keyChar
   }
+  LOG.trace("getChar: $res")
+  return res
 }
 
 private fun performSurround(pair: Pair<String, String>, range: TextRange, caret: VimCaret, tagsOnNewLines: Boolean = false) {

src/main/java/com/maddyhome/idea/vim/ui/ExOutputPanel.java

@@ -18,6 +18,7 @@
 import com.maddyhome.idea.vim.KeyHandler;
 import com.maddyhome.idea.vim.VimPlugin;
 import com.maddyhome.idea.vim.api.ExecutionContext;
+import com.maddyhome.idea.vim.diagnostic.VimLogger;
 import com.maddyhome.idea.vim.helper.HelperKt;
 import com.maddyhome.idea.vim.helper.MessageHelper;
 import com.maddyhome.idea.vim.helper.UiHelper;
@@ -59,6 +60,8 @@ public class ExOutputPanel extends JPanel {
 
   private boolean myActive = false;
 
+  private static final VimLogger LOG = injector.getLogger(ExOutputPanel.class);
+
   private ExOutputPanel(@NotNull Editor editor) {
     myEditor = editor;
 
@@ -299,6 +302,10 @@ private void close(final @Nullable KeyEvent e) {
         final KeyStroke key = KeyStroke.getKeyStrokeForEvent(e);
         final List<KeyStroke> keys = new ArrayList<>(1);
         keys.add(key);
+        if (LOG.isTrace()) {
+          LOG.trace("Adding new keys to keyStack as part of playback. State before adding keys: " +
+                    KeyHandler.getInstance().getKeyStack().dump());
+        }
         KeyHandler.getInstance().getKeyStack().addKeys(keys);
         ExecutionContext.Editor context = injector.getExecutionContextManager().onEditor(new IjVimEditor(myEditor), null);
         VimPlugin.getMacro().playbackKeys(new IjVimEditor(myEditor), context, 1);

src/main/java/com/maddyhome/idea/vim/ui/ModalEntry.kt

@@ -8,6 +8,9 @@
 
 package com.maddyhome.idea.vim.ui
 
+import com.intellij.openapi.diagnostic.Logger
+import com.intellij.openapi.diagnostic.logger
+import com.intellij.openapi.diagnostic.trace
 import com.maddyhome.idea.vim.KeyHandler
 import com.maddyhome.idea.vim.api.VimEditor
 import com.maddyhome.idea.vim.helper.isCloseKeyStroke
@@ -22,13 +25,19 @@ import javax.swing.KeyStroke
  * @author dhleong
  */
 public object ModalEntry {
+
+  public val LOG: Logger = logger<ModalEntry>()
+
   public inline fun activate(editor: VimEditor, crossinline processor: (KeyStroke) -> Boolean) {
     // Firstly we pull the unfinished keys of the current mapping
     val mappingStack = KeyHandler.getInstance().keyStack
+    LOG.trace("Dumping key stack:")
+    LOG.trace { mappingStack.dump() }
     var stroke = mappingStack.feedSomeStroke()
     while (stroke != null) {
       val result = processor(stroke)
       if (!result) {
+        LOG.trace("Got char from mapping stack")
         return
       }
       stroke = mappingStack.feedSomeStroke()
@@ -55,6 +64,7 @@ public object ModalEntry {
           KeyHandler.getInstance().modalEntryKeys += stroke
         }
         if (!processor(stroke)) {
+          LOG.trace("Got char from keyboard input: $stroke. Event: $e")
           KeyboardFocusManager.getCurrentKeyboardFocusManager().removeKeyEventDispatcher(this)
           loop.exit()
         }

vim-engine/src/main/kotlin/com/maddyhome/idea/vim/key/KeyStack.kt

@@ -9,6 +9,8 @@
 package com.maddyhome.idea.vim.key
 
 import com.maddyhome.idea.vim.api.injector
+import com.maddyhome.idea.vim.diagnostic.trace
+import com.maddyhome.idea.vim.diagnostic.vimLogger
 import javax.swing.KeyStroke
 
 /**
@@ -42,6 +44,7 @@ public class KeyStack {
   }
 
   public fun addKeys(keyStrokes: List<KeyStroke>) {
+    LOG.trace { "Got new keys to key stack: $keyStrokes" }
     stack.addFirst(Frame(keyStrokes))
   }
 
@@ -56,6 +59,23 @@ public class KeyStack {
       stack.first().resetPointer()
     }
   }
+
+  public fun dump(): String {
+    return buildString {
+      this.appendLine("KeyStack:")
+      this.appendLine("Stack size: ${stack.size}")
+      stack.forEachIndexed { index, frame ->
+        this.appendLine("Frame $index:")
+        this.appendLine("Keys: ${frame.keys}")
+        this.appendLine("Pointer: ${frame.pointer}")
+        this.appendLine()
+      }
+    }
+  }
+
+  private companion object {
+    private val LOG = vimLogger<KeyStack>()
+  }
 }
 
 private class Frame(

vim-engine/src/main/kotlin/com/maddyhome/idea/vim/key/MappingInfo.kt

@@ -16,21 +16,22 @@ import com.maddyhome.idea.vim.api.ImmutableVimCaret
 import com.maddyhome.idea.vim.api.VimEditor
 import com.maddyhome.idea.vim.api.injector
 import com.maddyhome.idea.vim.command.Argument
-import com.maddyhome.idea.vim.state.mode.Mode
 import com.maddyhome.idea.vim.command.OperatorArguments
-import com.maddyhome.idea.vim.state.mode.SelectionType.CHARACTER_WISE
-import com.maddyhome.idea.vim.state.VimStateMachine
-import com.maddyhome.idea.vim.state.mode.selectionType
 import com.maddyhome.idea.vim.common.Offset
 import com.maddyhome.idea.vim.common.argumentCaptured
 import com.maddyhome.idea.vim.common.offset
+import com.maddyhome.idea.vim.diagnostic.trace
 import com.maddyhome.idea.vim.diagnostic.vimLogger
 import com.maddyhome.idea.vim.extension.ExtensionHandler
 import com.maddyhome.idea.vim.group.visual.VimSelection
 import com.maddyhome.idea.vim.group.visual.VimSelection.Companion.create
 import com.maddyhome.idea.vim.helper.VimNlsSafe
-import com.maddyhome.idea.vim.state.mode.mode
 import com.maddyhome.idea.vim.helper.vimStateMachine
+import com.maddyhome.idea.vim.state.VimStateMachine
+import com.maddyhome.idea.vim.state.mode.Mode
+import com.maddyhome.idea.vim.state.mode.SelectionType.CHARACTER_WISE
+import com.maddyhome.idea.vim.state.mode.mode
+import com.maddyhome.idea.vim.state.mode.selectionType
 import com.maddyhome.idea.vim.vimscript.model.CommandLineVimLContext
 import com.maddyhome.idea.vim.vimscript.model.expressions.Expression
 import java.awt.event.KeyEvent
@@ -90,6 +91,7 @@ public class ToKeysMappingInfo(
     val editorDataContext = injector.executionContextManager.onEditor(editor, context)
     val fromIsPrefix = KeyHandler.isPrefix(fromKeys, toKeys)
     val keyHandler = KeyHandler.getInstance()
+    LOG.trace { "Adding new keys to keyStack as toKeys of mapping. State before adding keys: ${keyHandler.keyStack.dump()}" }
     keyHandler.keyStack.addKeys(toKeys)
     var first = true
     while (keyHandler.keyStack.hasStroke()) {

vim-engine/src/main/kotlin/com/maddyhome/idea/vim/macro/VimMacroBase.kt

@@ -14,6 +14,7 @@ import com.maddyhome.idea.vim.api.VimEditor
 import com.maddyhome.idea.vim.api.injector
 import com.maddyhome.idea.vim.diagnostic.VimLogger
 import com.maddyhome.idea.vim.diagnostic.debug
+import com.maddyhome.idea.vim.diagnostic.trace
 import com.maddyhome.idea.vim.diagnostic.vimLogger
 import javax.swing.KeyStroke
 
@@ -44,6 +45,10 @@ public abstract class VimMacroBase : VimMacro {
       } else {
         injector.parser.parseKeys(register.rawText)
       }
+
+      logger.trace {
+        "Adding new keys to keyStack as part of playback. State before adding keys: ${KeyHandler.getInstance().keyStack.dump()}"
+      }
       KeyHandler.getInstance().keyStack.addKeys(keys)
       playbackKeys(editor, context, count)
     } finally {