Improves logging with timestamps and granularity

CHANGELOG.md

@@ -1,5 +1,11 @@
 # Change Log
 
+## 4.0.2
+
+**Changed**
+
+- Refined the logging for granularity and reach. ([#60](https://github.com/ufukty/dim/issues/60))
+
 ## 4.0.1
 
 **Changed**

package.json

@@ -151,5 +151,5 @@
     "test": "npx vitest run",
     "vscode:prepublish": "npx tsc --noEmit && npx eslint src && node esbuild.mjs --production"
   },
-  "version": "4.0.1"
+  "version": "4.0.2"
 }

src/configManager.ts

@@ -2,6 +2,10 @@ import * as vscode from "vscode";
 import * as config from "./config";
 import * as models from "./models";
 
+function now(): string {
+  return new Date().toISOString();
+}
+
 type ScopeId = string;
 
 class Scope {
@@ -94,7 +98,7 @@ class Compiler {
 
   compile(scope: Scope): models.Config {
     try {
-      this.logger.appendLine(`config.Compiler: compiling user config for ${scope}`);
+      this.logger.appendLine(`${now()} config.Compiler: compiling user config for ${scope}`);
       const raw = this.reader.read(scope);
       const rules = this.rules(raw);
       return {
@@ -124,7 +128,7 @@ export class Cache {
   for(editor: vscode.TextEditor): models.Config {
     try {
       const scope = new Scope(editor);
-      this.logger.appendLine(`config.Manager: requested user config for ${scope}`);
+      this.logger.appendLine(`${now()} config.Manager: requested user config for ${scope}`);
       const i = scope.internalize();
       let c = this.cache.get(i);
       if (!c) {
@@ -138,7 +142,7 @@ export class Cache {
   }
 
   invalidate() {
-    this.logger.appendLine("config.Manager: invalidating cache");
+    this.logger.appendLine(`${now()} config.Manager: invalidating cache`);
     this.cache.clear();
   }
 }

src/editorDecorator.ts

@@ -1,8 +1,19 @@
 import * as vscode from "vscode";
-import * as utils from "./utilities";
 import * as cm from "./configManager";
 import * as models from "./models";
 
+function now(): string {
+  return new Date().toISOString();
+}
+
+export function sprintPos(pos: vscode.Position): string {
+  return `${pos.line + 1}:${pos.character + 1}`;
+}
+
+export function sprintRange(range: vscode.Range): string {
+  return `[${sprintPos(range.start)}, ${sprintPos(range.end)}]`;
+}
+
 export class EditorDecorator {
   private editor: vscode.TextEditor;
   private config: models.Config;
@@ -25,11 +36,15 @@ export class EditorDecorator {
     this.inFocus = true;
     this.filename = editor.document.fileName.split("/").pop() ?? "";
     this.lastUpdateTimestamp = 0;
-    this.logger.appendLine(`${this.filename}: constructor (enabled: ${enabled})`);
+    this.log(`constructor (enabled: ${enabled})`);
     this.config = this.configManager.for(this.editor);
     this.withConfig();
   }
 
+  private log(message: string) {
+    this.logger.appendLine(`${now()} editorDecorator(${this.filename}): ${message}`);
+  }
+
   private withConfig() {
     if (this.decoTypes) this.disposeLastDecorations();
     this.decoTypes = {
@@ -67,35 +82,33 @@ export class EditorDecorator {
   }
 
   private scanForRule(range: vscode.Range, rule: models.Rule): vscode.Range[] {
-    this.logger.appendLine(`${this.filename}: scanning for: ${rule.regex}`);
+    this.log(`scanning for: ${rule.regex}...`);
     const ranges: vscode.Range[] = [];
     const text = this.editor.document.getText(range);
     Array.from(text.matchAll(rule.regex)).forEach((match) => {
       if (!match.index || !match[0]) return;
       const start = match.index;
       const end = start + match[0].length;
       const range = new vscode.Range(this.editor.document.positionAt(start), this.editor.document.positionAt(end));
-      if (this.doBracesMatch(text, start, end)) {
-        this.logger.appendLine(`${this.filename}: scanning for: ${rule.regex}: found: ${utils.SprintRange(range)}`);
-        ranges.push(range);
-      }
+      if (this.doBracesMatch(text, start, end)) ranges.push(range);
     });
+    this.log(`found: ${ranges.map(sprintRange).join(", ")}`);
     return ranges;
   }
 
   private scanForRules() {
     const range = this.editor.document.validateRange(
       new vscode.Range(new vscode.Position(0, 0), new vscode.Position(2000, 0)),
     );
-    this.logger.appendLine(`${this.filename}: scanning lines: ${utils.SprintRange(range)}`);
+    this.log(`scanning lines: ${sprintRange(range)}`);
     this.matches = new Map() as Map<models.Rule, vscode.Range[]>;
     for (const rule of this.config.rules) {
       this.matches.set(rule, this.scanForRule(range, rule));
     }
   }
 
   private disposeLastDecorations() {
-    this.logger.appendLine(`${this.filename}: disposing previous decorations`);
+    this.log(`disposing previous decorations`);
     if (!this.decoTypes) return;
     this.editor.setDecorations(this.decoTypes.max, []);
     this.editor.setDecorations(this.decoTypes.mid, []);
@@ -104,6 +117,7 @@ export class EditorDecorator {
 
   private mergeIntersecting(queue: vscode.Range[]): vscode.Range[] {
     if (queue.length <= 1) return queue;
+    this.log(`merging ${queue.length} matches...`);
     const sorted = queue.sort((a, b) => {
       if (a.end.isBeforeOrEqual(b.start)) return -1; //   no overlap:      aabb
       if (b.end.isBeforeOrEqual(a.start)) return 1; //    no overlap:      bbaa
@@ -114,20 +128,13 @@ export class EditorDecorator {
     const merged = [] as vscode.Range[];
     let merging = sorted[0];
     for (let i = 1; i < sorted.length; i++) {
-      if (sorted[i].intersection(merging)) {
-        let m = merging;
-        const before = utils.SprintRange(m);
-        m = sorted[i];
-        const after = utils.SprintRange(m);
-        merging = merging.union(sorted[i]);
-        const mergd = utils.SprintRange(merging);
-        this.logger.appendLine(`${this.filename}: merging ${before} with ${after} to ${mergd}`);
-      } else {
+      if (!sorted[i].intersection(merging)) {
         merged.push(merging);
         merging = sorted[i];
       }
     }
     merged.push(merging);
+    this.log(`merged to ${merged.length}`);
     return merged;
   }
 
@@ -164,16 +171,16 @@ export class EditorDecorator {
   }
 
   private decorateEditor() {
-    this.logger.appendLine(`${this.filename}: decorating...`);
+    this.log(`decorating...`);
     const start = Date.now();
     if (!this.matches) this.scanForRules();
     this.applyNewDecorations();
-    this.logger.appendLine(`${this.filename}: decorated (${Date.now() - start}ms)`);
+    this.log(`decorated (${Date.now() - start}ms)`);
   }
 
   private schedule() {
     if (!this.enabled) {
-      this.logger.appendLine(this.filename + ": skipping update because Dim is disabled for this editor");
+      this.log(`skipping update because Dim is disabled for this editor`);
       return;
     }
     const period = this.config.updatePeriod;
@@ -192,44 +199,44 @@ export class EditorDecorator {
   }
 
   blur() {
-    this.logger.appendLine(`${this.filename}: blur`);
+    this.log(`blur`);
     this.inFocus = false;
   }
 
   focus() {
-    this.logger.appendLine(`${this.filename}: focus`);
+    this.log(`focus`);
     this.inFocus = true;
     this.schedule();
   }
 
   contentChange() {
-    this.logger.appendLine(`${this.filename}: content change`);
+    this.log(`content change`);
     this.matches = undefined;
     this.schedule();
   }
 
   selectionChange() {
-    this.logger.appendLine(`${this.filename}: selection change`);
+    this.log(`selection change`);
     this.schedule();
   }
 
   configChange() {
-    this.logger.appendLine(`${this.filename}: configuration change`);
+    this.log(`configuration change`);
     this.config = this.configManager.for(this.editor);
     this.matches = undefined;
     this.withConfig();
     this.schedule();
   }
 
   enable() {
-    this.logger.appendLine(`${this.filename}: enabling...`);
+    this.log(`enabling...`);
     this.enabled = true;
     this.matches = undefined;
     this.schedule();
   }
 
   disable() {
-    this.logger.appendLine(`${this.filename}: disabling...`);
+    this.log(`disabling...`);
     this.enabled = false;
     this.disposeLastDecorations();
   }

src/extension.ts

@@ -2,6 +2,10 @@ import * as vscode from "vscode";
 import { EditorDecorator } from "./editorDecorator";
 import { Cache } from "./configManager";
 
+function now(): string {
+  return new Date().toISOString();
+}
+
 class ExtensionLifecycleController {
   decorators: Map<vscode.TextEditor, EditorDecorator>;
   logger: vscode.OutputChannel;
@@ -13,7 +17,7 @@ class ExtensionLifecycleController {
   constructor(context: vscode.ExtensionContext) {
     this.context = context;
     this.logger = vscode.window.createOutputChannel("dim");
-    this.logger.appendLine("init");
+    this.logger.appendLine(`${now()} extension: init`);
     this.decorators = new Map();
     this.config = new Cache(this.logger);
     this.documentState = new Map<string, boolean>();
@@ -52,6 +56,7 @@ class ExtensionLifecycleController {
         this.activeEditor = undefined;
         return;
       }
+      this.logger.appendLine(`${now()} extension: onDidChangeActiveTextEditor: ${editor?.document?.uri?.toString()}`);
 
       if (this.activeEditor && editor === this.activeEditor) return;
 
@@ -83,7 +88,7 @@ class ExtensionLifecycleController {
         event.document.uri.path === this.activeEditor.document.uri.path &&
         event.document.uri.scheme === "file"
       ) {
-        this.logger.appendLine("onDidChangeTextDocument");
+        this.logger.appendLine(`${now()} extension: onDidChangeTextDocument: ${event?.reason}`);
         this.decorators.get(this.activeEditor)?.contentChange();
       }
     } catch (e) {
@@ -92,6 +97,7 @@ class ExtensionLifecycleController {
   }
 
   onDidChangeConfiguration(e: vscode.ConfigurationChangeEvent) {
+    this.logger.appendLine(`${now()} extension: onDidChangeConfiguration: ${e?.affectsConfiguration}`);
     try {
       if (e.affectsConfiguration("dim")) {
         this.config.invalidate();
@@ -105,6 +111,7 @@ class ExtensionLifecycleController {
   }
 
   onCommandReceiveDisableDimForCurrentEditor() {
+    this.logger.appendLine(`${now()} extension: disableDimForCurrentEditor`);
     try {
       if (this.activeEditor) {
         const ad = this.decorators.get(this.activeEditor);
@@ -122,6 +129,7 @@ class ExtensionLifecycleController {
   }
 
   onCommandReceiveEnableDimForCurrentEditor() {
+    this.logger.appendLine(`${now()} extension: enableDimForCurrentEditor`);
     try {
       if (this.activeEditor) {
         const ad = this.decorators.get(this.activeEditor);
@@ -136,6 +144,7 @@ class ExtensionLifecycleController {
   }
 
   onCommandReceiveToggleDimForCurrentEditor() {
+    this.logger.appendLine(`${now()} extension: toggleDimForCurrentEditor`);
     try {
       if (!this.activeEditor) return;
       const ad = this.decorators.get(this.activeEditor);
@@ -151,6 +160,7 @@ class ExtensionLifecycleController {
   onDidChangeTextEditorSelection(event: vscode.TextEditorSelectionChangeEvent) {
     try {
       if (this.activeEditor && this.activeEditor === event.textEditor) {
+        this.logger.appendLine(`${now()} extension: change selections: ${event?.kind}/${event?.selections?.length}`);
         this.decorators.get(this.activeEditor)?.selectionChange();
       }
     } catch (e) {
@@ -159,6 +169,7 @@ class ExtensionLifecycleController {
   }
 
   destroy() {
+    this.logger.appendLine(`${now()} extension: destroy`);
     try {
       for (const editor of vscode.window.visibleTextEditors) {
         this.decorators.get(editor)?.disable();