More logging

Author: Sertion

CHANGELOG.md

@@ -1,6 +1,7 @@
 # Change Log
 
 ## 11.0.2 (July 17, 2024)
+* Feature: Adding logging behind the `debug` and `trace` levels.
 * Fix: Updating dependencies
 
 ## 11.0.1 (May 29, 2024)

esbuild.mjs

@@ -12,7 +12,8 @@ await build({
 		"node:child_process",
 		"node:fs",
 		"node:fs/promises",
-		"node:url",
 		"node:path",
+		"node:url",
+		"node:util",
 	],
 });

package-lock.json

@@ -32,7 +32,7 @@
   "scripts": {
     "vscode:prepublish": "npm run build",
     "build": "node esbuild.mjs",
-    "package": "npx vsce package",
+    "package": "npx @vscode/vsce package",
     "lint": "biome ci ./src",
     "pretest": "tsc --project tsconfig.test.json",
     "test": "npm run pretest && node ./out/test/run-test.js"
@@ -45,10 +45,10 @@
     "@types/sinonjs__fake-timers": "8.1.5",
     "@types/vscode": "1.91.0",
     "@vscode/test-electron": "2.4.1",
-    "esbuild": "0.23.0",
-    "mocha": "10.6.0",
+    "esbuild": "0.23.1",
+    "mocha": "10.7.3",
     "sinon": "18.0.0",
-    "typescript": "5.5.3"
+    "typescript": "5.5.4"
   },
   "homepage": "https://github.com/Sertion/vscode-gitblame/blob/main/README.md",
   "bugs": {

package.json

@@ -38,7 +38,8 @@ export class Blamer {
 			return;
 		}
 
-		let resolve: (blame: Promise<Blame | undefined>) => void = () => {};
+		let resolve: (blame: Promise<Blame | undefined> | undefined) => void =
+			() => {};
 		this.files.set(
 			fileName,
 			new Promise<Blame | undefined>((res) => {
@@ -49,15 +50,27 @@ export class Blamer {
 		const { file, gitRoot } = await this.create(fileName);
 
 		if (file === undefined) {
-			resolve(Promise.resolve(undefined));
+			resolve(undefined);
 			return;
 		}
 
+		Logger.debug("Setting up file watcher for '%s'", file.fileName);
+
 		this.fsWatchers.set(
 			file.fileName,
-			watch(file.fileName, () => {
-				this.remove(file.fileName);
-			}),
+			watch(
+				file.fileName,
+				{
+					persistent: false,
+				},
+				() => {
+					Logger.debug(
+						"File watcher callback for '%s' executed",
+						file.fileName,
+					);
+					this.remove(file.fileName);
+				},
+			),
 		);
 
 		const blame = this.blameQueue.add(() => file.getBlame());
@@ -95,6 +108,7 @@ export class Blamer {
 		this.files.delete(fileName);
 		this.fsWatchers.get(fileName)?.close();
 		this.fsWatchers.delete(fileName);
+		Logger.debug("Cache for '%s' cleared. File watcher closed.", fileName);
 	}
 
 	public dispose(): void {

src/git/blame.ts

@@ -35,6 +35,11 @@ export class File {
 
 		const commitRegistry: CommitRegistry = new Map();
 		for await (const chunk of this.process?.stdout ?? []) {
+			Logger.debug(
+				"Got chunk from '%s' git blame process. Size: %d",
+				realFileName,
+				chunk.length,
+			);
 			yield* processChunk(chunk, commitRegistry);
 		}
 		for await (const error of this.process?.stderr ?? []) {
@@ -50,6 +55,12 @@ export class File {
 
 		try {
 			for await (const lineAttachedCommit of this.run(realpathFileName)) {
+				Logger.trace(
+					"Found blame information for %s:%d: hash:%s",
+					realpathFileName,
+					lineAttachedCommit.line.result,
+					lineAttachedCommit.commit.hash,
+				);
 				blameInfo.set(lineAttachedCommit.line.result, lineAttachedCommit);
 			}
 		} catch (err) {

src/git/file.ts

@@ -1,5 +1,6 @@
 import { type FSWatcher, watch } from "node:fs";
 import { join, resolve } from "node:path";
+import { Logger } from "../util/logger.js";
 import { getGitFolder } from "./util/git-command.js";
 
 export type HeadChangeEvent = {
@@ -34,22 +35,32 @@ export class HeadWatch {
 		}
 
 		const repositoryRoot = resolve(gitRoot, "..");
+		const HEADFile = join(gitRoot, "HEAD");
 
 		this.heads.set(
 			gitRoot,
 			watch(
-				join(gitRoot, "HEAD"),
+				HEADFile,
 				{
 					persistent: false,
 				},
-				() => this.callback({ gitRoot, repositoryRoot }),
+				() => {
+					Logger.debug("File watcher callback for '%s' called.", HEADFile);
+					this.callback({ gitRoot, repositoryRoot });
+				},
 			),
 		);
+
+		Logger.debug("File watcher for '%s' created.", HEADFile);
 	}
 
 	public dispose(): void {
-		for (const [, headWatcher] of this.heads) {
+		for (const [gitRoot, headWatcher] of this.heads) {
 			headWatcher.close();
+			Logger.debug(
+				"File watcher for HEAD file in git root '%s' closed.",
+				gitRoot,
+			);
 		}
 		this.heads.clear();
 		this.filesWithFoundHeads.clear();

src/git/head-watch.ts

@@ -1,3 +1,5 @@
+import { Logger } from "../util/logger";
+
 export class Queue<
 	ReturnValue = void,
 	QueueFunction extends () => Promise<ReturnValue> = () => Promise<ReturnValue>,
@@ -17,6 +19,10 @@ export class Queue<
 			if (this.processing.size < this.maxParallel) {
 				this.startFunction(toQueue);
 			} else {
+				Logger.debug(
+					"Already running %s in parallel. Adding execution to queue.",
+					this.maxParallel,
+				);
 				this.list.push(toQueue);
 			}
 		});

src/git/queue.ts

@@ -1,3 +1,4 @@
+import { format } from "node:util";
 import { type LogOutputChannel, window } from "vscode";
 
 export class Logger {
@@ -25,6 +26,14 @@ export class Logger {
 		Logger.getInstance().out.info(info);
 	}
 
+	public static debug(debug: string, ...args: (string | number)[]): void {
+		Logger.getInstance().out.debug(format(debug, ...args));
+	}
+
+	public static trace(debug: string, ...args: (string | number)[]): void {
+		Logger.getInstance().out.trace(format(debug, ...args));
+	}
+
 	public dispose(): void {
 		Logger.instance = undefined;
 		this.out.dispose();

src/util/logger.ts

@@ -14,6 +14,7 @@ import type { Commit } from "./git/util/stream-parsing.js";
 
 import { isUncommitted } from "./git/util/is-hash.js";
 import { getActiveTextEditor } from "./util/get-active.js";
+import { Logger } from "./util/logger.js";
 import { getProperty } from "./util/property.js";
 import {
 	toInlineTextView,
@@ -107,25 +108,25 @@ export class StatusBarView {
 	}
 
 	private command(): string {
-		const action = getProperty("statusBarMessageClickAction");
-
-		if (action === "Open tool URL") {
-			return "gitblame.online";
-		}
-		if (action === "Open git show") {
-			return "gitblame.gitShow";
-		}
-		if (action === "Copy hash to clipboard") {
-			return "gitblame.addCommitHashToClipboard";
-		}
-
-		return "gitblame.quickInfo";
+		return {
+			"Open tool URL": "gitblame.online",
+			"Open git show": "gitblame.gitShow",
+			"Copy hash to clipboard": "gitblame.addCommitHashToClipboard",
+			"Show info message": "gitblame.quickInfo",
+		}[getProperty("statusBarMessageClickAction")];
 	}
 
 	private updateStatusBar(statusBar: StatusBarItem) {
 		statusBar.text = this.statusBarText;
 		statusBar.tooltip = this.statusBarTooltip;
 		statusBar.command = this.statusBarCommand ? this.command() : undefined;
+
+		Logger.debug(
+			"Updating status bar item with: Text:'%s', tooltip:'git blame%s', command:%s",
+			statusBar.text,
+			statusBar.tooltip,
+			statusBar.command ?? "",
+		);
 	}
 
 	private text(text: string, command: boolean, tooltip = ""): void {
@@ -160,15 +161,15 @@ export class StatusBarView {
 		if (!getProperty("inlineMessageEnabled")) {
 			return;
 		}
-		const margin = getProperty("inlineMessageMargin");
-		const decorationPosition = new Position(
-			editor.selection.active.line,
-			Number.MAX_SAFE_INTEGER,
-		);
 
 		this.removeLineDecoration();
 		// Add new decoration
 		if (useDelay && (await this.delayUpdate(getProperty("delayBlame")))) {
+			const margin = getProperty("inlineMessageMargin");
+			const decorationPosition = new Position(
+				editor.selection.active.line,
+				Number.MAX_SAFE_INTEGER,
+			);
 			editor.setDecorations?.(this.decorationType, [
 				{
 					renderOptions: {
@@ -192,8 +193,8 @@ export class StatusBarView {
 	public preUpdate(
 		textEditor: PartialTextEditor | undefined,
 	): textEditor is PartialTextEditor {
-		this.clear();
 		if (!validEditor(textEditor)) {
+			this.clear();
 			return false;
 		}
 		for (const rejects of this.ongoingViewUpdateRejects) {