feat: log to outputChannel (#2623)

* fix: ensure we don't create a new modehandler

* feat: add logger. refactor console.log to use logger

* fix: show error message if copy fails. closes #2614

* refactor: move logger until util folder. print to console too

* fix: restore travis script just so we can get travisbuddy working

.travis.yml

@@ -35,14 +35,15 @@ before_install:
     sleep 3;
   fi
 
-before_script:
-- npm run build
+script:
 - npm run forceprettier
 - if [[ $(git diff-index HEAD -- *.js *.ts) ]]; then
     git diff;
     echo "Prettier Failed. Run `gulp` or `gulp forceprettier`";
     exit 1;
   fi
+- npm run build
+- npm test --silent
 
 before_deploy:
 - npm install -g vsce;

extension.ts

@@ -20,6 +20,7 @@ import { Notation } from './src/configuration/notation';
 import { StatusBar } from './src/statusBar';
 import { taskQueue } from './src/taskQueue';
 import { ModeHandlerMap } from './src/mode/modeHandlerMap';
+import { Logger } from './src/util/logger';
 
 let extensionContext: vscode.ExtensionContext;
 
@@ -46,9 +47,7 @@ export async function getAndUpdateModeHandler(): Promise<ModeHandler> {
 
   curHandler.vimState.editor = vscode.window.activeTextEditor!;
   if (!prevHandler || curHandler.vimState.identity !== prevHandler!.vimState.identity) {
-    setTimeout(() => {
-      curHandler.syncCursors();
-    }, 0);
+    curHandler.syncCursors();
   }
 
   if (previousActiveEditorId.hasSameBuffer(activeEditorId)) {
@@ -95,7 +94,10 @@ export async function activate(context: vscode.ExtensionContext) {
   extensionContext = context;
   let compositionState = new CompositionState();
 
-  // Event to update active configuration items when changed without restarting vscode
+  extensionContext.subscriptions.push(StatusBar);
+  extensionContext.subscriptions.push(Logger);
+
+  // Reload active configurations
   vscode.workspace.onDidChangeConfiguration(() => {
     configuration.reload();
   });
@@ -107,12 +109,9 @@ export async function activate(context: vscode.ExtensionContext) {
       return;
     }
 
-    /**
-     * Change from vscode editor should set document.isDirty to true but they initially don't!
-     * There is a timing issue in vscode codebase between when the isDirty flag is set and
-     * when registered callbacks are fired. https://github.com/Microsoft/vscode/issues/11339
-     */
-
+    // Change from vscode editor should set document.isDirty to true but they initially don't!
+    // There is a timing issue in vscode codebase between when the isDirty flag is set and
+    // when registered callbacks are fired. https://github.com/Microsoft/vscode/issues/11339
     let contentChangeHandler = (modeHandler: ModeHandler) => {
       if (modeHandler.vimState.currentMode === ModeName.Insert) {
         if (modeHandler.vimState.historyTracker.currentContentChanges === undefined) {
@@ -234,14 +233,15 @@ export async function activate(context: vscode.ExtensionContext) {
   vscode.workspace.onDidCloseTextDocument(async event => {
     const documents = vscode.workspace.textDocuments;
 
-    // Delete modehandler if vscode knows NOTHING about this document. This does
-    // not handle the case of the same file open twice. This only handles the
-    // case of deleting a modehandler once all tabs of this document have been
-    // closed
+    // Delete modehandler once all tabs of this document have been closed
     for (let editorIdentity of ModeHandlerMap.getKeys()) {
-      let [modeHandler] = await ModeHandlerMap.getOrCreate(editorIdentity);
-      const editor = modeHandler.vimState.editor;
-      if (editor === undefined || documents.indexOf(editor.document) === -1) {
+      let modeHandler = await ModeHandlerMap.get(editorIdentity);
+
+      if (
+        modeHandler == null ||
+        modeHandler.vimState.editor === undefined ||
+        documents.indexOf(modeHandler.vimState.editor.document) === -1
+      ) {
         ModeHandlerMap.delete(editorIdentity);
       }
     }
@@ -364,5 +364,5 @@ async function handleActiveEditorChange(): Promise<void> {
 }
 
 process.on('unhandledRejection', function(reason: any, p: any) {
-  console.log('Unhandled Rejection at: Promise ', p, ' reason: ', reason);
+  Logger.debug(`Unhandled Rejection at: Promise ${p}. Reason: ${reason}.`);
 });

gulpfile.js

@@ -9,7 +9,7 @@ var gulp = require('gulp'),
 
 // compile
 gulp.task('compile', function() {
-  let isError = false;
+  var isError = false;
 
   var tsProject = ts.createProject('tsconfig.json', { noEmitOnError: true });
   var tsResult = tsProject

package.json

@@ -590,6 +590,7 @@
     "untildify": "3.0.2"
   },
   "devDependencies": {
+    "@types/clipboardy": "1.1.0",
     "@types/copy-paste": "1.1.30",
     "@types/diff": "3.5.1",
     "@types/diff-match-patch": "1.0.32",

src/cmd_line/commandLine.ts

@@ -7,11 +7,12 @@ import { StatusBar } from '../statusBar';
 import * as parser from './parser';
 import * as util from '../util';
 import { VimError, ErrorCode } from '../error';
+import { Logger } from '../util/logger';
 
 export class CommandLine {
   public static async PromptAndRun(initialText: string, vimState: VimState): Promise<void> {
     if (!vscode.window.activeTextEditor) {
-      console.log('CommandLine: No active document.');
+      Logger.debug('CommandLine: No active document');
       return;
     }
 

src/history/historyTracker.ts

@@ -17,6 +17,7 @@ import { Position } from './../common/motion/position';
 import { RecordedState } from './../state/recordedState';
 import { VimState } from './../state/vimState';
 import { TextEditor } from './../textEditor';
+import { Logger } from './../util/logger';
 
 const diffEngine = new DiffMatchPatch.diff_match_patch();
 diffEngine.Diff_Timeout = 1; // 1 second
@@ -182,9 +183,9 @@ export class HistoryTracker {
 
   private get currentHistoryStep(): HistoryStep {
     if (this.currentHistoryStepIndex === -1) {
-      console.log('Tried to modify history at index -1');
-
-      throw new Error();
+      let msg = 'HistoryTracker: Tried to modify history at index -1';
+      Logger.debug(msg);
+      throw new Error(msg);
     }
 
     return this.historySteps[this.currentHistoryStepIndex];
@@ -454,7 +455,7 @@ export class HistoryTracker {
    */
   async undoAndRemoveChanges(n: number): Promise<void> {
     if (this.currentHistoryStep.changes.length < n) {
-      console.log('Something bad happened in removeChange');
+      Logger.debug('HistoryTracker: Something bad happened in removeChange');
       return;
     }
 

src/mode/modeHandler.ts

@@ -30,12 +30,12 @@ import {
   TextTransformations,
 } from './../transformations/transformations';
 import { Mode, ModeName, VSCodeVimCursorType } from './mode';
+import { Logger } from '../util/logger';
 
 export class ModeHandler implements vscode.Disposable {
   private _disposables: vscode.Disposable[] = [];
   private _modes: Mode[];
   private _remappers: Remappers;
-  public debugId: number; // Used solely for debugging purposes
 
   public vimState: VimState;
 
@@ -44,7 +44,6 @@ export class ModeHandler implements vscode.Disposable {
   }
 
   constructor() {
-    this.debugId = Math.floor(Math.random() * 1000);
     this._remappers = new Remappers();
     this._modes = [
       new modes.NormalMode(),
@@ -71,16 +70,31 @@ export class ModeHandler implements vscode.Disposable {
     // This also makes things like gd work.
     // For whatever reason, the editor positions aren't updated until after the
     // stack clears, which is why this setTimeout is necessary
-    setTimeout(() => {
-      this.syncCursors();
-    }, 0);
+    this.syncCursors();
 
     // Handle scenarios where mouse used to change current position.
-    const disposable = vscode.window.onDidChangeTextEditorSelection(e => {
+    const onChangeTextEditorSelection = vscode.window.onDidChangeTextEditorSelection(e => {
       if (configuration.disableExt) {
         return;
       }
 
+      if (Globals.isTesting) {
+        return;
+      }
+
+      if (e.textEditor !== this.vimState.editor) {
+        return;
+      }
+
+      if (this.vimState.focusChanged) {
+        this.vimState.focusChanged = false;
+        return;
+      }
+
+      if (this.currentMode.name === ModeName.EasyMotionMode) {
+        return;
+      }
+
       taskQueue.enqueueTask(
         () => this.handleSelectionChange(e),
         undefined,
@@ -92,7 +106,7 @@ export class ModeHandler implements vscode.Disposable {
       );
     });
 
-    this._disposables.push(disposable);
+    this._disposables.push(onChangeTextEditorSelection);
     this._disposables.push(this.vimState);
   }
 
@@ -112,23 +126,6 @@ export class ModeHandler implements vscode.Disposable {
    * perform the manual testing.
    */
   private async handleSelectionChange(e: vscode.TextEditorSelectionChangeEvent): Promise<void> {
-    if (Globals.isTesting) {
-      return;
-    }
-
-    if (e.textEditor !== this.vimState.editor) {
-      return;
-    }
-
-    if (this.vimState.focusChanged) {
-      this.vimState.focusChanged = false;
-      return;
-    }
-
-    if (this.currentMode.name === ModeName.EasyMotionMode) {
-      return;
-    }
-
     let selection = e.selections[0];
     if (
       (e.selections.length !== this.vimState.allCursors.length || this.vimState.isMultiCursor) &&
@@ -868,7 +865,7 @@ export class ModeHandler implements vscode.Disposable {
 
     if (textTransformations.length > 0) {
       if (areAnyTransformationsOverlapping(textTransformations)) {
-        console.log(
+        Logger.debug(
           `Text transformations are overlapping. Falling back to serial
            transformations. This is generally a very bad sign. Try to make
            your text transformations operate on non-overlapping ranges.`
@@ -1437,16 +1434,18 @@ export class ModeHandler implements vscode.Disposable {
 
   // Syncs cursors between vscode representation and vim representation
   syncCursors() {
-    if (this.vimState.editor) {
-      this.vimState.cursorStartPosition = Position.FromVSCodePosition(
-        this.vimState.editor.selection.start
-      );
-      this.vimState.cursorPosition = Position.FromVSCodePosition(
-        this.vimState.editor.selection.start
-      );
-      this.vimState.desiredColumn = this.vimState.cursorPosition.character;
+    setTimeout(() => {
+      if (this.vimState.editor) {
+        this.vimState.cursorStartPosition = Position.FromVSCodePosition(
+          this.vimState.editor.selection.start
+        );
+        this.vimState.cursorPosition = Position.FromVSCodePosition(
+          this.vimState.editor.selection.start
+        );
+        this.vimState.desiredColumn = this.vimState.cursorPosition.character;
 
-      this.vimState.prevSelection = this.vimState.editor.selection;
-    }
+        this.vimState.prevSelection = this.vimState.editor.selection;
+      }
+    }, 0);
   }
 }

src/neovim/neovim.ts

@@ -10,6 +10,7 @@ import { Register, RegisterMode } from '../register/register';
 import { TextEditor } from '../textEditor';
 import { Position } from './../common/motion/position';
 import { VimState } from './../state/vimState';
+import { Logger } from '../util/logger';
 
 export class Neovim implements vscode.Disposable {
   private process: ChildProcess;
@@ -24,8 +25,7 @@ export class Neovim implements vscode.Disposable {
       cwd: dir,
     });
     this.process.on('error', err => {
-      console.log(err);
-      vscode.window.showErrorMessage('Unable to setup neovim instance! Check your path.');
+      Logger.error(err.message, `Neovim: Error spawning neovim. Error=${err.message}.`);
       configuration.enableNeovim = false;
     });
     this.nvim = await attach(this.process.stdin, this.process.stdout);
@@ -115,7 +115,9 @@ export class Neovim implements vscode.Disposable {
       fixedLines.join('\n')
     );
 
-    console.log(`${lines.length} lines in nvim but ${TextEditor.getLineCount()} in editor.`);
+    Logger.debug(
+      `Neovim: ${lines.length} lines in nvim but ${TextEditor.getLineCount()} in editor.`
+    );
 
     let [row, character] = ((await this.nvim.callFunction('getpos', ['.'])) as Array<number>).slice(
       1,

src/state/vimState.ts

@@ -13,6 +13,7 @@ import { GlobalState } from './../state/globalState';
 import { ReplaceState } from './../state/replaceState';
 import { RecordedState } from './recordedState';
 import { Neovim } from '../neovim/neovim';
+import { Logger } from '../util/logger';
 
 /**
  * The VimState class holds permanent state that carries over from action
@@ -146,7 +147,7 @@ export class VimState implements vscode.Disposable {
   public set allCursors(value: Range[]) {
     for (const cursor of value) {
       if (!cursor.start.isValid() || !cursor.stop.isValid()) {
-        console.log('invalid value for set cursor position. This is probably bad?');
+        Logger.debug('VimState: invalid value for set cursor position. This is probably bad?');
       }
     }
 

src/util.ts

@@ -3,6 +3,7 @@ import * as vscode from 'vscode';
 
 import { Position } from './common/motion/position';
 import { Range } from './common/motion/range';
+import { Logger } from './util/logger';
 
 export async function showInfo(message: string): Promise<{}> {
   return vscode.window.showInformationMessage('Vim: ' + message) as {};
@@ -12,11 +13,15 @@ export async function showError(message: string): Promise<{}> {
   return vscode.window.showErrorMessage('Vim: ' + message) as {};
 }
 
-const clipboardy = require('clipboardy');
+import * as clipboardy from 'clipboardy';
 
 export class Clipboard {
   public static Copy(text: string) {
-    clipboardy.writeSync(text);
+    try {
+      clipboardy.writeSync(text);
+    } catch (e) {
+      Logger.error(e, `Clipboard: Error copying to clipboard. Error=${e}`);
+    }
   }
 
   public static Paste(): string {

src/util/logger.ts

@@ -0,0 +1,64 @@
+import * as vscode from 'vscode';
+
+enum LoggingLevel {
+  Error = 0,
+  Warn = 1,
+  Debug = 2
+}
+
+class LoggerImpl implements vscode.Disposable {
+  private _channel: vscode.OutputChannel;
+
+  constructor() {
+    this._channel = vscode.window.createOutputChannel("vscodevim");
+  }
+
+  public debug(message?: string): void {
+    this.emitMessage(LoggingLevel.Debug, message);
+  }
+
+  public error(message?: string, friendlyMessage?: string): void {
+    this.emitMessage(LoggingLevel.Error, message);
+    vscode.window.showErrorMessage(`Error: ${friendlyMessage} || ${message}`);
+  }
+
+  private emitMessage(loggingLevel: LoggingLevel, message?: string) {
+    if (message === undefined) {
+      return;
+    }
+
+    message = `${LoggerImpl.getNow()} - ${message}`;
+
+    this._channel.appendLine(message);
+
+    switch (loggingLevel) {
+      case LoggingLevel.Error:
+        console.error(message);
+        break;
+      case LoggingLevel.Warn:
+        console.warn(message);
+        break;
+      case LoggingLevel.Debug:
+        console.log(message);
+        break;
+    }
+  }
+
+  private static getNow(): string {
+    const now = new Date();
+    let time = [ String(now.getHours()), String(now.getMinutes()), String(now.getSeconds()) ];
+    for (let i = 0; i < time.length; i++) {
+      if ( Number(time[i]) < 10 ) {
+        time[i] = "0" + time[i];
+      }
+    }
+
+    return time.join(':');
+  }
+
+  dispose() {
+    this._channel.dispose();
+  }
+}
+
+export let Logger = new LoggerImpl();