Skip to content

Commit

Permalink
feat!: use VSCode log level instead of our own (#1962)
Browse files Browse the repository at this point in the history 
* feat!: use VSCode log level instead of our own

* docs: add logging instructions to CONTRIBUTING.md

* docs: clean up CONTRIBUTING.md notes on log levels

* style: use outputChannel log level instead of one from environment

* fix: display error when log file fails to open

* style: move log level handler registration to init function
  • Loading branch information
@ollien
ollien committed May 14, 2024
1 parent 6c220c7 commit 5f1bc49
Show file tree
Hide file tree
Showing 6 changed files with 155 additions and 113 deletions.
17 changes: 13 additions & 4 deletions CONTRIBUTING.md
View file
Original file line number Diff line number Diff line change
Expand Up @@ -37,11 +37,20 @@ npx vsce package -o vscode-neovim.vsix

### Logging

You can observe the extension logs via the `vscode-neovim` Output channel or from the dev tools console (run the
`Developer: Toggle Developer Tools` vscode command to see the console).
You can view the extension logs in one of three locations

Note: some messages are not logged to the Output channel, to avoid infinite loop. This is decided by the
[`logToOutputChannel` parameter](https://github.com/vscode-neovim/vscode-neovim/blob/7337ffd5009067d074af5371171f277cb522aa9b/src/logger.ts#L184).
1. Via the `vscode-neovim` Output channel

- Note: some messages are not logged to the Output channel, to avoid infinite loop. This is decided by the
[`logToOutputChannel` parameter](https://github.com/vscode-neovim/vscode-neovim/blob/7337ffd5009067d074af5371171f277cb522aa9b/src/logger.ts#L184).

2. From the dev tools console (run the `Developer: Toggle Developer Tools` vscode command to see the console) by
enabling the `vscode-neovim.logOutputToConsole` setting.
3. From a log file of your choosing, by configuring the `vscode-neovim.logPath` setting.

VSCode, by default will only show messages at the "Info" level or above, but than can be changed by running the command
`Developer Set Log Level...` -> `vscode-neovim` and selecting the desired log level. You can also do this by clicking
the gear icon in the output pane, with `vscode-neovim` selected.

### Run Unit Tests

Expand Down
12 changes: 0 additions & 12 deletions package.json
View file
Original file line number Diff line number Diff line change
Expand Up @@ -295,18 +295,6 @@
"default": "",
"description": "Log file path"
},
"vscode-neovim.logLevel": {
"type": "string",
"default": "error",
"enum": [
"none",
"error",
"warn",
"info",
"debug"
],
"markdownDescription": "Log Level. See also `vscode-neovim.logOutputToConsole`."
},
"vscode-neovim.logOutputToConsole": {
"type": "boolean",
"default": false,
Expand Down
37 changes: 19 additions & 18 deletions src/buffer_manager.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -9,6 +9,7 @@ import {
Disposable,
EndOfLine,
EventEmitter,
LogLevel,
NotebookDocument,
Selection,
TextDocument,
Expand All @@ -27,7 +28,7 @@ import {
import actions from "./actions";
import { config } from "./config";
import { EventBusData, eventBus } from "./eventBus";
import { LogLevel, createLogger } from "./logger";
import { createLogger } from "./logger";
import { MainController } from "./main_controller";
import { ManualPromise, convertByteNumToCharNum, disposeAll, wait } from "./utils";

Expand Down Expand Up @@ -265,7 +266,7 @@ export class BufferManager implements Disposable {
doc ??= await workspace.openTextDocument(uri);
}
} catch (error) {
logger.log(doc?.uri, LogLevel.error, `Error opening file ${fileName}, ${error}`);
logger.log(doc?.uri, LogLevel.Error, `Error opening file ${fileName}, ${error}`);
}
if (!doc) {
return;
Expand Down Expand Up @@ -300,17 +301,17 @@ export class BufferManager implements Disposable {
}

const uri = Uri.parse(vscode_uri, true);
logger.log(uri, LogLevel.debug, `Buffer request for ${uri.fsPath}, bufId: ${bufnr}`);
logger.log(uri, LogLevel.Debug, `Buffer request for ${uri.fsPath}, bufId: ${bufnr}`);
try {
let doc = this.findDocFromUri(uri.toString());
if (!doc) {
logger.log(uri, LogLevel.debug, `Opening a doc: ${uri.fsPath}`);
logger.log(uri, LogLevel.Debug, `Opening a doc: ${uri.fsPath}`);
doc = await workspace.openTextDocument(uri);
}
if (!this.textDocumentToBufferId.has(doc)) {
logger.log(
uri,
LogLevel.debug,
LogLevel.Debug,
`No doc -> buffer mapping exists, assigning mapping and init buffer options`,
);
const buffers = await this.client.buffers;
Expand Down Expand Up @@ -473,37 +474,37 @@ export class BufferManager implements Disposable {
// Open/change neovim windows
for (const editor of visibleEditors) {
const { document: doc } = editor;
logger.log(doc.uri, LogLevel.debug, `Visible editor, viewColumn: ${editor.viewColumn}, doc: ${doc.uri}`);
logger.log(doc.uri, LogLevel.Debug, `Visible editor, viewColumn: ${editor.viewColumn}, doc: ${doc.uri}`);
// create buffer first if not known to the system
// creating initially not listed buffer to prevent firing autocmd events when
// buffer name/lines are not yet set. We'll set buflisted after setup
if (!this.textDocumentToBufferId.has(doc)) {
logger.log(doc.uri, LogLevel.debug, `Document not known, init in neovim`);
logger.log(doc.uri, LogLevel.Debug, `Document not known, init in neovim`);
const buf = await this.client.createBuffer(false, true);
if (typeof buf === "number") {
logger.error(`Cannot create a buffer, code: ${buf}`);
continue;
}
await this.initBufferForDocument(doc, buf, editor);

logger.log(doc.uri, LogLevel.debug, `Document: ${doc.uri}, BufId: ${buf.id}`);
logger.log(doc.uri, LogLevel.Debug, `Document: ${doc.uri}, BufId: ${buf.id}`);
this.textDocumentToBufferId.set(doc, buf.id);
}
if (this.textEditorToWinId.has(editor)) continue;
const editorBufferId = this.textDocumentToBufferId.get(doc)!;
try {
logger.log(
doc.uri,
LogLevel.debug,
LogLevel.Debug,
`Creating new window for ${editor.viewColumn} column (undefined is OK here)`,
);
const winId = await this.createNeovimWindow(editorBufferId);
logger.log(doc.uri, LogLevel.debug, `Created new window: ${winId} ViewColumn: ${editor.viewColumn}`);
logger.log(doc.uri, LogLevel.Debug, `Created new window: ${winId} ViewColumn: ${editor.viewColumn}`);
this.textEditorToWinId.set(editor, winId);
this.winIdToEditor.set(winId, editor);
await this.main.cursorManager.updateNeovimCursorPosition(editor, editor.selection.active);
} catch (e) {
logger.log(doc.uri, LogLevel.error, (e as Error).message);
logger.log(doc.uri, LogLevel.Error, (e as Error).message);
}
}
}
Expand All @@ -519,31 +520,31 @@ export class BufferManager implements Disposable {
// when in normal mode
logger.log(
uri,
LogLevel.error,
LogLevel.Error,
`Unable to determine neovim window id for editor, viewColumn: ${activeEditor.viewColumn}, docUri: ${uri}`,
);
return;
}
if ((await this.client.window).id === winId) return;
logger.log(
uri,
LogLevel.debug,
LogLevel.Debug,
`Setting active editor - viewColumn: ${activeEditor.viewColumn}, winId: ${winId}`,
);
await this.main.cursorManager.updateNeovimCursorPosition(activeEditor, activeEditor.selection.active);
if (this.main.modeManager.isVisualMode) {
// https://github.com/vscode-neovim/vscode-neovim/issues/1577
logger.log(
uri,
LogLevel.debug,
LogLevel.Debug,
`Cancel visual mode to prevent selection from previous editor to carry over to active editor`,
);
await this.client.input("<Esc>");
}
try {
await this.client.request("nvim_set_current_win", [winId]);
} catch (e) {
logger.log(uri, LogLevel.error, (e as Error).message);
logger.log(uri, LogLevel.Error, (e as Error).message);
}
}
// #endregion
Expand Down Expand Up @@ -574,11 +575,11 @@ export class BufferManager implements Disposable {
// the event notifying the doc provider of any changes
(async () => {
const uri = this.buildExternalBufferUri(await buffer.name, buffer.id);
logger.log(uri, LogLevel.debug, `received buffer event for ${uri}`);
logger.log(uri, LogLevel.Debug, `received buffer event for ${uri}`);
this.bufferProvider.documentDidChange.fire(uri);
return uri;
})().then(undefined, (e) => {
logger.log(undefined, LogLevel.error, `failed to notify document change: ${e}`);
logger.log(undefined, LogLevel.Error, `failed to notify document change: ${e}`);
});
};

Expand All @@ -588,7 +589,7 @@ export class BufferManager implements Disposable {
private async initBufferForDocument(document: TextDocument, buffer: Buffer, editor?: TextEditor): Promise<void> {
const bufId = buffer.id;
const { uri: docUri } = document;
logger.log(docUri, LogLevel.debug, `Init buffer for ${bufId}, doc: ${docUri}`);
logger.log(docUri, LogLevel.Debug, `Init buffer for ${bufId}, doc: ${docUri}`);

const eol = document.eol === EndOfLine.LF ? "\n" : "\r\n";
const lines = document.getText().split(eol);
Expand Down
51 changes: 28 additions & 23 deletions src/document_change_manager.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -9,11 +9,12 @@ import {
TextDocumentChangeEvent,
window,
workspace,
LogLevel,
} from "vscode";

import actions from "./actions";
import { BufferManager } from "./buffer_manager";
import { LogLevel, createLogger } from "./logger";
import { createLogger } from "./logger";
import { MainController } from "./main_controller";
import {
DotRepeatChange,
Expand Down Expand Up @@ -128,7 +129,7 @@ export class DocumentChangeManager implements Disposable {
}

private onBufferInit: BufferManager["onBufferInit"] = (id, doc) => {
logger.log(doc.uri, LogLevel.debug, `Init buffer content for bufId: ${id}, uri: ${doc.uri.toString()}`);
logger.log(doc.uri, LogLevel.Debug, `Init buffer content for bufId: ${id}, uri: ${doc.uri.toString()}`);
this.documentContentInNeovim.set(doc, doc.getText());
};

Expand All @@ -141,19 +142,19 @@ export class DocumentChangeManager implements Disposable {
more,
) => {
const doc = this.main.bufferManager.getTextDocumentForBufferId(bufId);
logger.log(doc?.uri, LogLevel.debug, `Received neovim buffer changed event for bufId: ${bufId}, tick: ${tick}`);
logger.log(doc?.uri, LogLevel.Debug, `Received neovim buffer changed event for bufId: ${bufId}, tick: ${tick}`);
if (!doc) {
logger.log(undefined, LogLevel.debug, `No text document for buffer: ${bufId}`);
logger.log(undefined, LogLevel.Debug, `No text document for buffer: ${bufId}`);
return;
}
const skipTick = this.bufferSkipTicks.get(bufId) || 0;
if (skipTick >= tick) {
logger.log(doc.uri, LogLevel.debug, `BufId: ${bufId} skipping tick: ${tick}`);
logger.log(doc.uri, LogLevel.Debug, `BufId: ${bufId} skipping tick: ${tick}`);
return;
}
// happens after undo
if (firstLine === lastLine && linedata.length === 0) {
logger.log(doc.uri, LogLevel.debug, `BufId: ${bufId} empty change, skipping`);
logger.log(doc.uri, LogLevel.Debug, `BufId: ${bufId} empty change, skipping`);
return;
}
if (!this.textDocumentChangePromise.has(doc)) {
Expand All @@ -169,7 +170,7 @@ export class DocumentChangeManager implements Disposable {

private applyEdits = async (): Promise<void> => {
this.applyingEdits = true;
logger.log(undefined, LogLevel.debug, `Applying neovim edits`);
logger.log(undefined, LogLevel.Debug, `Applying neovim edits`);
// const edits = this.pendingEvents.splice(0);
let resolveProgress: undefined | (() => void);
const progressTimer = setTimeout(() => {
Expand All @@ -186,10 +187,10 @@ export class DocumentChangeManager implements Disposable {
const [bufId, _tick, firstLine, lastLine, data, _more] = edit;
const doc = this.main.bufferManager.getTextDocumentForBufferId(bufId);
if (!doc) {
logger.log(undefined, LogLevel.warn, `No document for ${bufId}, skip`);
logger.log(undefined, LogLevel.Warning, `No document for ${bufId}, skip`);
continue;
}
logger.log(doc.uri, LogLevel.debug, `Accumulating edits for ${doc.uri.toString()}, bufId: ${bufId}`);
logger.log(doc.uri, LogLevel.Debug, `Accumulating edits for ${doc.uri.toString()}, bufId: ${bufId}`);
if (!newTextByDoc.get(doc)) {
newTextByDoc.set(doc, getDocumentLineArray(doc));
}
Expand Down Expand Up @@ -244,14 +245,14 @@ export class DocumentChangeManager implements Disposable {
for (const [doc, newLines] of newTextByDoc) {
const lastPromiseIdx = this.textDocumentChangePromise.get(doc)?.length || 0;
try {
logger.log(doc.uri, LogLevel.debug, `Applying edits for ${doc.uri.toString()}`);
logger.log(doc.uri, LogLevel.Debug, `Applying edits for ${doc.uri.toString()}`);
if (doc.isClosed) {
logger.log(doc.uri, LogLevel.debug, `Document was closed, skippnig`);
logger.log(doc.uri, LogLevel.Debug, `Document was closed, skippnig`);
continue;
}
const editor = window.visibleTextEditors.find((e) => e.document === doc);
if (!editor) {
logger.log(doc.uri, LogLevel.debug, `No visible text editor for document, skipping`);
logger.log(doc.uri, LogLevel.Debug, `No visible text editor for document, skipping`);
continue;
}
const oldText = doc.getText().replace(/\r\n/g, "\n");
Expand Down Expand Up @@ -281,19 +282,23 @@ export class DocumentChangeManager implements Disposable {
}
this.cursorAfterTextDocumentChange.set(editor.document, editor.selection.active);
docPromises.forEach((p) => p.resolve && p.resolve());
logger.log(doc.uri, LogLevel.debug, `Changes succesfully applied for ${doc.uri.toString()}`);
logger.log(doc.uri, LogLevel.Debug, `Changes succesfully applied for ${doc.uri.toString()}`);
this.documentContentInNeovim.set(doc, doc.getText());
} else {
docPromises.forEach((p) => {
p.promise.catch(() =>
logger.log(doc.uri, LogLevel.warn, `Edit was canceled for doc: ${doc.uri.toString()}`),
logger.log(
doc.uri,
LogLevel.Warning,
`Edit was canceled for doc: ${doc.uri.toString()}`,
),
);
p.reject();
});
logger.log(doc.uri, LogLevel.warn, `Changes were not applied for ${doc.uri.toString()}`);
logger.log(doc.uri, LogLevel.Warning, `Changes were not applied for ${doc.uri.toString()}`);
}
} catch (e) {
logger.log(doc.uri, LogLevel.error, `Error applying neovim edits, error: ${(e as Error).message}`);
logger.log(doc.uri, LogLevel.Error, `Error applying neovim edits, error: ${(e as Error).message}`);
}
}
}
Expand All @@ -320,7 +325,7 @@ export class DocumentChangeManager implements Disposable {
if (origText == null) {
logger.log(
doc.uri,
LogLevel.warn,
LogLevel.Warning,
`Can't get last known neovim content for ${doc.uri.toString()}, skipping`,
);
return;
Expand All @@ -332,20 +337,20 @@ export class DocumentChangeManager implements Disposable {
private onChangeTextDocumentLocked = async (e: TextDocumentChangeEvent, origText: string): Promise<void> => {
const { document: doc, contentChanges } = e;

logger.log(doc.uri, LogLevel.debug, `Change text document for uri: ${doc.uri.toString()}`);
logger.log(doc.uri, LogLevel.Debug, `Change text document for uri: ${doc.uri.toString()}`);
logger.log(
doc.uri,
LogLevel.debug,
LogLevel.Debug,
`Version: ${doc.version}, skipVersion: ${this.documentSkipVersionOnChange.get(doc)}`,
);
if ((this.documentSkipVersionOnChange.get(doc) ?? 0) >= doc.version) {
logger.log(doc.uri, LogLevel.debug, `Skipping a change since versions equals`);
logger.log(doc.uri, LogLevel.Debug, `Skipping a change since versions equals`);
return;
}

const bufId = this.main.bufferManager.getBufferIdForTextDocument(doc);
if (!bufId) {
logger.log(doc.uri, LogLevel.warn, `No neovim buffer for ${doc.uri.toString()}`);
logger.log(doc.uri, LogLevel.Warning, `No neovim buffer for ${doc.uri.toString()}`);
return;
}

Expand Down Expand Up @@ -379,13 +384,13 @@ export class DocumentChangeManager implements Disposable {

const bufTick: number = await this.client.request("nvim_buf_get_changedtick", [bufId]);
if (!bufTick) {
logger.log(doc.uri, LogLevel.warn, `Can't get changed tick for bufId: ${bufId}, deleted?`);
logger.log(doc.uri, LogLevel.Warning, `Can't get changed tick for bufId: ${bufId}, deleted?`);
return;
}

this.bufferSkipTicks.set(bufId, bufTick + changeArgs.length);

logger.log(doc.uri, LogLevel.debug, `Setting wantInsertCursorUpdate to false`);
logger.log(doc.uri, LogLevel.Debug, `Setting wantInsertCursorUpdate to false`);
this.main.cursorManager.wantInsertCursorUpdate = false;

await actions.lua("handle_changes", bufId, changeArgs);
Expand Down
4 changes: 2 additions & 2 deletions src/extension.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -4,7 +4,7 @@ import actions from "./actions";
import { config } from "./config";
import { EXT_ID, EXT_NAME } from "./constants";
import { eventBus } from "./eventBus";
import { LogLevel, createLogger, logger as rootLogger } from "./logger";
import { createLogger, logger as rootLogger } from "./logger";
import { MainController } from "./main_controller";
import { VSCodeContext, disposeAll } from "./utils";

Expand All @@ -31,7 +31,7 @@ export async function activate(context: vscode.ExtensionContext, isRestart = fal
disposables.push(outputChannel);

config.init();
rootLogger.init(LogLevel[config.logLevel], config.logPath, config.outputToConsole, outputChannel);
rootLogger.init(outputChannel.logLevel, config.logPath, config.outputToConsole, outputChannel);
eventBus.init();
actions.init();
context.subscriptions.push(
Expand Down

0 comments on commit 5f1bc49

Please sign in to comment.