Adds @debug, @log, @logName decorators

Adds Logger.debug, Logger.logWithDebugParams
Refactors logging and renames TraceLevel to LogLevel
Adds logging for views and view nodes

src/logger.ts

@@ -1,15 +1,17 @@
 'use strict';
 import { ConfigurationChangeEvent, ExtensionContext, OutputChannel, window } from 'vscode';
-import { configuration, OutputLevel } from './configuration';
+import { configuration, LogLevel } from './configuration';
 import { extensionOutputChannelName } from './constants';
 // import { Telemetry } from './telemetry';
 
+export { LogLevel } from './configuration';
+
 const ConsolePrefix = `[${extensionOutputChannelName}]`;
 
 const isDebuggingRegex = /\bgitlens\b/i;
 
 export class Logger {
-    static level: OutputLevel = OutputLevel.Silent;
+    static level: LogLevel = LogLevel.Silent;
     static output: OutputChannel | undefined;
 
     static configure(context: ExtensionContext) {
@@ -22,9 +24,9 @@ export class Logger {
 
         const section = configuration.name('outputLevel').value;
         if (initializing || configuration.changed(e, section)) {
-            this.level = configuration.get<OutputLevel>(section);
+            this.level = configuration.get<LogLevel>(section);
 
-            if (this.level === OutputLevel.Silent) {
+            if (this.level === LogLevel.Silent) {
                 if (this.output !== undefined) {
                     this.output.dispose();
                     this.output = undefined;
@@ -36,50 +38,65 @@ export class Logger {
         }
     }
 
-    static log(message?: any, ...params: any[]): void {
-        if (this.level !== OutputLevel.Verbose && this.level !== OutputLevel.Debug) return;
+    static debug(message?: any, ...params: any[]): void {
+        if (this.level !== LogLevel.Debug && !Logger.isDebugging) return;
 
         if (Logger.isDebugging) {
             console.log(this.timestamp, ConsolePrefix, message, ...params);
         }
 
         if (this.output !== undefined) {
-            this.output.appendLine(
-                (Logger.isDebugging ? [this.timestamp, message, ...params] : [message, ...params]).join(' ')
-            );
+            this.output.appendLine(`${this.timestamp} ${message} ${this.toLoggableParams(true, params)}`);
         }
     }
 
-    static error(ex: Error, classOrMethod?: string, ...params: any[]): void {
-        if (this.level === OutputLevel.Silent) return;
-
+    static error(ex: Error, message?: string, ...params: any[]): void {
         if (Logger.isDebugging) {
-            console.error(this.timestamp, ConsolePrefix, classOrMethod, ...params, ex);
+            console.error(this.timestamp, ConsolePrefix, message, ...params, ex);
         }
 
+        if (this.level === LogLevel.Silent) return;
+
         if (this.output !== undefined) {
-            this.output.appendLine(
-                (Logger.isDebugging
-                    ? [this.timestamp, classOrMethod, ...params, ex]
-                    : [classOrMethod, ...params, ex]
-                ).join(' ')
-            );
+            this.output.appendLine(`${this.timestamp} ${message} ${this.toLoggableParams(false, params)}\n${ex}`);
         }
 
         // Telemetry.trackException(ex);
     }
 
-    static warn(message?: any, ...params: any[]): void {
-        if (this.level === OutputLevel.Silent) return;
+    static log(message?: any, ...params: any[]): void {
+        if (Logger.isDebugging) {
+            console.log(this.timestamp, ConsolePrefix, message, ...params);
+        }
+
+        if (this.level !== LogLevel.Verbose && this.level !== LogLevel.Debug) return;
+
+        if (this.output !== undefined) {
+            this.output.appendLine(`${this.timestamp} ${message} ${this.toLoggableParams(false, params)}`);
+        }
+    }
+
+    static logWithDebugParams(message?: any, ...params: any[]): void {
+        if (Logger.isDebugging) {
+            console.log(this.timestamp, ConsolePrefix, message, ...params);
+        }
+
+        if (this.level !== LogLevel.Verbose && this.level !== LogLevel.Debug) return;
+
+        if (this.output !== undefined) {
+            this.output.appendLine(`${this.timestamp} ${message} ${this.toLoggableParams(true, params)}`);
+        }
+    }
 
+    static warn(message?: any, ...params: any[]): void {
         if (Logger.isDebugging) {
             console.warn(this.timestamp, ConsolePrefix, message, ...params);
         }
 
+        if (this.level === LogLevel.Silent) return;
+
         if (this.output !== undefined) {
-            this.output.appendLine(
-                (Logger.isDebugging ? [this.timestamp, message, ...params] : [message, ...params]).join(' ')
-            );
+            this.output.appendLine(`${this.timestamp} ${message} ${this.toLoggableParams(false, params)}`);
         }
     }
 
@@ -91,35 +108,38 @@ export class Logger {
 
     private static get timestamp(): string {
         const now = new Date();
-        const time = now
+        return `[${now
             .toISOString()
             .replace(/T/, ' ')
-            .replace(/\..+/, '');
-        return `[${time}:${('00' + now.getUTCMilliseconds()).slice(-3)}]`;
+            .replace(/\..+/, '')}:${('00' + now.getUTCMilliseconds()).slice(-3)}]`;
     }
 
     static gitOutput: OutputChannel | undefined;
 
     static logGitCommand(command: string, ex?: Error): void {
-        if (this.level !== OutputLevel.Debug) return;
+        if (this.level !== LogLevel.Debug) return;
 
         if (this.gitOutput === undefined) {
             this.gitOutput = window.createOutputChannel(`${extensionOutputChannelName} (Git)`);
         }
-        this.gitOutput.appendLine(`${this.timestamp} ${command}${ex === undefined ? '' : `\n\n${ex.toString()}`}`);
+        this.gitOutput.appendLine(`${this.timestamp} ${command}${ex != null ? `\n\n${ex.toString()}` : ''}`);
+    }
+
+    private static toLoggableParams(debugOnly: boolean, params: any[]) {
+        if (params.length === 0 || (debugOnly && this.level !== LogLevel.Debug && !Logger.isDebugging)) {
+            return '';
+        }
+
+        const loggableParams = params.map(p => (typeof p === 'object' ? JSON.stringify(p) : String(p))).join(', ');
+        return loggableParams || '';
     }
 
     private static _isDebugging: boolean | undefined;
     static get isDebugging() {
         if (this._isDebugging === undefined) {
-            try {
-                const env = process.env;
-                this._isDebugging =
-                    env && env.VSCODE_DEBUGGING_EXTENSION
-                        ? isDebuggingRegex.test(env.VSCODE_DEBUGGING_EXTENSION)
-                        : false;
-            }
-            catch {}
+            const env = process.env;
+            this._isDebugging =
+                env && env.VSCODE_DEBUGGING_EXTENSION ? isDebuggingRegex.test(env.VSCODE_DEBUGGING_EXTENSION) : false;
         }
 
         return this._isDebugging;

src/system.ts

@@ -3,6 +3,7 @@
 export * from './system/array';
 // export * from './system/asyncIterable';
 export * from './system/date';
+export * from './system/decorators';
 // export * from './system/disposable';
 // export * from './system/element';
 // export * from './system/event';

src/system/decorators.ts

@@ -0,0 +1,232 @@
+'use strict';
+import { Logger, LogLevel } from '../logger';
+import { Strings } from './string';
+
+function decorate(decorator: (fn: Function, key: string) => Function): Function {
+    return (target: any, key: string, descriptor: any) => {
+        let fn;
+        let fnKey;
+
+        if (typeof descriptor.value === 'function') {
+            fn = descriptor.value;
+            fnKey = 'value';
+        }
+        else if (typeof descriptor.get === 'function') {
+            fn = descriptor.get;
+            fnKey = 'get';
+        }
+
+        if (!fn || !fnKey) throw new Error('Not supported');
+
+        descriptor[fnKey] = decorator(fn, key);
+    };
+}
+
+let correlationCounter = 0;
+
+export interface LogContext<T> {
+    prefix: string;
+    name: string;
+    instance: T;
+    instanceName: string;
+    id?: number;
+}
+
+export const LogInstanceNameFn = Symbol('logInstanceNameFn');
+
+export function debug<T>(
+    options: {
+        args?: boolean | { [arg: string]: (arg: any) => string };
+        correlate?: boolean;
+        enter?(this: any, ...args: any[]): string;
+        exit?(this: any, result: any): string;
+        prefix?(this: any, context: LogContext<T>, ...args: any[]): string;
+        timed?: boolean;
+    } = { args: true, timed: true }
+) {
+    return log<T>({ debug: true, ...options });
+}
+
+export function logName<T>(fn: (c: T, name: string) => string) {
+    return (target: Function) => {
+        (target as any)[LogInstanceNameFn] = fn;
+    };
+}
+
+export function log<T>(
+    options: {
+        args?: boolean | { [arg: string]: (arg: any) => string };
+        correlate?: boolean;
+        debug?: boolean;
+        enter?(this: any, ...args: any[]): string;
+        exit?(this: any, result: any): string;
+        prefix?(this: any, context: LogContext<T>, ...args: any[]): string;
+        timed?: boolean;
+    } = { args: true, timed: true }
+) {
+    options = { args: true, timed: true, ...options };
+
+    const logFn = options.debug ? Logger.debug.bind(Logger) : Logger.log.bind(Logger);
+
+    return (target: any, key: string, descriptor: PropertyDescriptor) => {
+        if (!(typeof descriptor.value === 'function')) throw new Error('not supported');
+
+        const fn = descriptor.value;
+
+        const isClass = Boolean(target && target.constructor);
+
+        const fnBody = fn.toString().replace(/((\/\/.*$)|(\/\*[\s\S]*?\*\/))/gm, '');
+        const parameters: string[] =
+            fnBody.slice(fnBody.indexOf('(') + 1, fnBody.indexOf(')')).match(/([^\s,]+)/g) || [];
+
+        descriptor.value = function(this: any, ...args: any[]) {
+            if (Logger.level === LogLevel.Debug || (Logger.level === LogLevel.Verbose && !options.debug)) {
+                let instanceName;
+                if (this != null) {
+                    if (this.constructor && this.constructor[LogInstanceNameFn]) {
+                        instanceName = target.constructor[LogInstanceNameFn](this, this.constructor.name);
+                    }
+                    else {
+                        instanceName = this.constructor.name;
+                    }
+                }
+                else {
+                    instanceName = '';
+                }
+
+                let correlationId;
+                let prefix: string;
+                if (options.correlate || options.timed) {
+                    correlationId = correlationCounter++;
+                    if (options.correlate) {
+                        // If we are correlating, get the class fn in order to store the correlationId if needed
+                        (isClass ? target[key] : fn).logCorrelationId = correlationId;
+                    }
+                    prefix = `[${correlationId.toString(16)}] ${instanceName ? `${instanceName}.` : ''}${key}`;
+                }
+                else {
+                    prefix = `${instanceName ? `${instanceName}.` : ''}${key}`;
+                }
+
+                if (options.prefix != null) {
+                    prefix = options.prefix(
+                        {
+                            prefix: prefix,
+                            instance: this,
+                            name: key,
+                            instanceName: instanceName,
+                            id: correlationId
+                        } as LogContext<T>,
+                        ...args
+                    );
+                }
+
+                if (!options.args || args.length === 0) {
+                    if (options.enter != null) {
+                        logFn(prefix, options.enter(...args));
+                    }
+                    else {
+                        logFn(prefix);
+                    }
+                }
+                else {
+                    let loggableParams = args
+                        .map((v: any, index: number) => {
+                            const p = parameters[index];
+
+                            let loggable;
+                            if (typeof options.args === 'object' && options.args[p]) {
+                                loggable = options.args[p](v);
+                            }
+                            else {
+                                loggable =
+                                    typeof v === 'object'
+                                        ? JSON.stringify(v, this.sanitizeSerializableParam)
+                                        : String(v);
+                            }
+
+                            return p ? `${p}=${loggable}` : loggable;
+                        })
+                        .join(', ');
+
+                    if (options.enter != null) {
+                        loggableParams = `${options.enter(...args)} ${loggableParams}`;
+                    }
+
+                    if (options.debug) {
+                        Logger.debug(prefix, loggableParams);
+                    }
+                    else {
+                        Logger.logWithDebugParams(prefix, loggableParams);
+                    }
+                }
+
+                if (options.timed || options.exit != null) {
+                    const start = options.timed ? process.hrtime() : undefined;
+                    const result = fn.apply(this, args);
+
+                    if (
+                        result != null &&
+                        (typeof result === 'object' || typeof result === 'function') &&
+                        typeof result.then === 'function'
+                    ) {
+                        const promise = result.then((r: any) => {
+                            const timing =
+                                start !== undefined ? ` \u2022 ${Strings.getDurationMilliseconds(start)} ms` : '';
+                            let exit;
+                            try {
+                                exit = options.exit != null ? options.exit(r) : '';
+                            }
+                            catch (ex) {
+                                exit = `@log.exit error: ${ex}`;
+                            }
+                            logFn(prefix, `completed${timing}${exit}`);
+                        });
+
+                        if (typeof promise.catch === 'function') {
+                            promise.catch((ex: any) => {
+                                const timing =
+                                    start !== undefined ? ` \u2022 ${Strings.getDurationMilliseconds(start)} ms` : '';
+                                Logger.error(ex, prefix, `failed${timing}`);
+                            });
+                        }
+                    }
+                    else {
+                        const timing =
+                            start !== undefined ? ` \u2022 ${Strings.getDurationMilliseconds(start)} ms` : '';
+                        let exit;
+                        try {
+                            exit = options.exit !== undefined ? options.exit(result) : '';
+                        }
+                        catch (ex) {
+                            exit = `@log.exit error: ${ex}`;
+                        }
+                        logFn(key, `completed${timing}${exit}`);
+                    }
+                    return result;
+                }
+            }
+
+            return fn.apply(this, args);
+        };
+    };
+}
+
+function _memoize(fn: Function, key: string): Function {
+    const memoizeKey = `$memoize$${key}`;
+
+    return function(this: any, ...args: any[]) {
+        if (!this.hasOwnProperty(memoizeKey)) {
+            Object.defineProperty(this, memoizeKey, {
+                configurable: false,
+                enumerable: false,
+                writable: false,
+                value: fn.apply(this, args)
+            });
+        }
+
+        return this[memoizeKey];
+    };
+}
+
+export const memoize = decorate(_memoize);

src/ui/config.ts

@@ -77,7 +77,7 @@ export enum KeyMap {
     None = 'none'
 }
 
-export enum OutputLevel {
+export enum LogLevel {
     Silent = 'silent',
     Errors = 'errors',
     Verbose = 'verbose',
@@ -319,7 +319,7 @@ export interface Config {
         };
     };
     modes: { [key: string]: ModeConfig };
-    outputLevel: OutputLevel;
+    outputLevel: LogLevel;
     recentChanges: {
         highlight: {
             locations: HighlightLocations[];

src/views/nodes/fileHistoryNode.ts

@@ -11,7 +11,7 @@ import {
     RepositoryFileSystemChangeEvent
 } from '../../git/gitService';
 import { Logger } from '../../logger';
-import { Iterables } from '../../system';
+import { debug, Iterables } from '../../system';
 import { FileHistoryView } from '../fileHistoryView';
 import { CommitFileNode, CommitFileNodeDisplayAs } from './commitFileNode';
 import { MessageNode } from './common';
@@ -100,6 +100,7 @@ export class FileHistoryNode extends SubscribeableViewNode {
         return item;
     }
 
+    @debug()
     protected async subscribe() {
         const repo = await Container.git.getRepository(this.uri);
         if (repo === undefined) return undefined;
@@ -126,7 +127,9 @@ export class FileHistoryNode extends SubscribeableViewNode {
     private onRepoFileSystemChanged(e: RepositoryFileSystemChangeEvent) {
         if (!e.uris.some(uri => uri.toString(true) === this.uri.toString(true))) return;
 
-        Logger.log(`FileHistoryNode.onRepoFileSystemChanged; triggering node refresh`);
+        Logger.debug(
+            `FileHistoryNode${this.id}.onRepoFileSystemChanged(${this.uri.toString(true)}); triggering node refresh`
+        );
 
         void this.triggerChange();
     }

src/views/nodes/fileHistoryTrackerNode.ts

@@ -4,7 +4,7 @@ import { Disposable, TextEditor, TreeItem, TreeItemCollapsibleState, Uri, window
 import { UriComparer } from '../../comparers';
 import { Container } from '../../container';
 import { GitUri } from '../../git/gitService';
-import { Functions } from '../../system';
+import { debug, Functions, log } from '../../system';
 import { FileHistoryView } from '../fileHistoryView';
 import { MessageNode } from './common';
 import { FileHistoryNode } from './fileHistoryNode';
@@ -23,6 +23,7 @@ export class FileHistoryTrackerNode extends SubscribeableViewNode
         this.resetChild();
     }
 
+    @debug()
     resetChild() {
         if (this._child !== undefined) {
             this._child.dispose();
@@ -102,16 +103,19 @@ export class FileHistoryTrackerNode extends SubscribeableViewNode
         return false;
     }
 
+    @log()
     setEditorFollowing(enabled: boolean) {
         this.canSubscribe = enabled;
     }
 
+    @debug()
     protected async subscribe() {
         return Disposable.from(
             window.onDidChangeActiveTextEditor(Functions.debounce(this.onActiveEditorChanged, 500), this)
         );
     }
 
+    @debug({ args: false })
     private onActiveEditorChanged(editor: TextEditor | undefined) {
         void this.triggerChange();
     }

src/views/nodes/lineHistoryNode.ts

@@ -10,7 +10,7 @@ import {
     RepositoryFileSystemChangeEvent
 } from '../../git/gitService';
 import { Logger } from '../../logger';
-import { Iterables } from '../../system';
+import { debug, Iterables } from '../../system';
 import { LineHistoryView } from '../lineHistoryView';
 import { CommitFileNode, CommitFileNodeDisplayAs } from './commitFileNode';
 import { MessageNode } from './common';
@@ -124,6 +124,7 @@ export class LineHistoryNode extends SubscribeableViewNode {
         return item;
     }
 
+    @debug()
     protected async subscribe() {
         const repo = await Container.git.getRepository(this.uri);
         if (repo === undefined) return undefined;
@@ -150,7 +151,7 @@ export class LineHistoryNode extends SubscribeableViewNode {
     private onRepoFileSystemChanged(e: RepositoryFileSystemChangeEvent) {
         if (!e.uris.some(uri => uri.toString(true) === this.uri.toString(true))) return;
 
-        Logger.log(`LineHistoryNode.onRepoFileSystemChanged; triggering node refresh`);
+        Logger.debug(`LineHistoryNode.onRepoFileSystemChanged(${this.uri.toString(true)}); triggering node refresh`);
 
         void this.triggerChange();
     }

src/views/nodes/lineHistoryTrackerNode.ts

@@ -3,7 +3,7 @@ import { Disposable, Selection, TreeItem, TreeItemCollapsibleState, window } fro
 import { UriComparer } from '../../comparers';
 import { Container } from '../../container';
 import { GitUri } from '../../git/gitService';
-import { Functions } from '../../system';
+import { debug, Functions, log } from '../../system';
 import { LinesChangeEvent } from '../../trackers/gitLineTracker';
 import { LineHistoryView } from '../lineHistoryView';
 import { MessageNode } from './common';
@@ -24,6 +24,7 @@ export class LineHistoryTrackerNode extends SubscribeableViewNode
         this.resetChild();
     }
 
+    @debug()
     resetChild() {
         if (this._child !== undefined) {
             this._child.dispose();
@@ -94,10 +95,12 @@ export class LineHistoryTrackerNode extends SubscribeableViewNode
         return false;
     }
 
+    @log()
     setEditorFollowing(enabled: boolean) {
         this.canSubscribe = enabled;
     }
 
+    @debug()
     protected async subscribe() {
         if (Container.lineTracker.isSubscribed(this)) return undefined;
 
@@ -115,6 +118,7 @@ export class LineHistoryTrackerNode extends SubscribeableViewNode
         );
     }
 
+    @debug({ args: false })
     private onActiveLinesChanged(e: LinesChangeEvent) {
         void this.triggerChange();
     }

src/views/nodes/repositoriesNode.ts

@@ -3,7 +3,7 @@ import { Disposable, ProgressLocation, TextEditor, TreeItem, TreeItemCollapsible
 import { Container } from '../../container';
 import { GitUri } from '../../git/gitService';
 import { Logger } from '../../logger';
-import { Functions } from '../../system';
+import { debug, Functions, log } from '../../system';
 import { RepositoriesView } from '../repositoriesView';
 import { RefreshReason } from '../viewBase';
 import { MessageNode } from './common';
@@ -57,6 +57,7 @@ export class RepositoriesNode extends SubscribeableViewNode {
         return item;
     }
 
+    @log()
     async fetchAll() {
         if (this._children === undefined || this._children.length === 0) return;
 
@@ -85,6 +86,7 @@ export class RepositoriesNode extends SubscribeableViewNode {
         );
     }
 
+    @log()
     async pullAll() {
         if (this._children === undefined || this._children.length === 0) return;
 
@@ -153,6 +155,7 @@ export class RepositoriesNode extends SubscribeableViewNode {
         void this.ensureSubscription();
     }
 
+    @debug()
     protected async subscribe() {
         const subscriptions = [Container.git.onDidChangeRepositories(this.onRepositoriesChanged, this)];
 
@@ -165,6 +168,7 @@ export class RepositoriesNode extends SubscribeableViewNode {
         return Disposable.from(...subscriptions);
     }
 
+    @debug({ args: false })
     private async onActiveEditorChanged(editor: TextEditor | undefined) {
         if (editor == null || this._children === undefined || this._children.length === 1) {
             return;
@@ -195,6 +199,7 @@ export class RepositoriesNode extends SubscribeableViewNode {
         }
     }
 
+    @debug()
     private onRepositoriesChanged() {
         void this.triggerChange();
     }

src/views/nodes/repositoryNode.ts

@@ -13,8 +13,7 @@ import {
     RepositoryChangeEvent,
     RepositoryFileSystemChangeEvent
 } from '../../git/gitService';
-import { Logger } from '../../logger';
-import { Dates, Functions, Strings } from '../../system';
+import { Dates, debug, Functions, log, Strings } from '../../system';
 import { RepositoriesView } from '../repositoriesView';
 import { BranchesNode } from './branchesNode';
 import { BranchNode } from './branchNode';
@@ -169,6 +168,7 @@ export class RepositoryNode extends SubscribeableViewNode {
         return item;
     }
 
+    @log()
     async fetch(progress: boolean = true) {
         if (!progress) return this.fetchCore();
 
@@ -189,6 +189,7 @@ export class RepositoryNode extends SubscribeableViewNode {
         this.view.triggerNodeChange(this);
     }
 
+    @log()
     async pull(progress: boolean = true) {
         if (!progress) return this.pullCore();
 
@@ -209,6 +210,7 @@ export class RepositoryNode extends SubscribeableViewNode {
         this.view.triggerNodeChange(this);
     }
 
+    @log()
     async push(progress: boolean = true) {
         if (!progress) return this.pushCore();
 
@@ -235,6 +237,7 @@ export class RepositoryNode extends SubscribeableViewNode {
         void this.ensureSubscription();
     }
 
+    @debug()
     protected async subscribe() {
         const disposables = [this.repo.onDidChange(this.onRepoChanged, this)];
 
@@ -257,13 +260,25 @@ export class RepositoryNode extends SubscribeableViewNode {
         return this.view.config.includeWorkingTree;
     }
 
+    @debug({
+        args: {
+            e: (e: RepositoryFileSystemChangeEvent) =>
+                `{ repository: ${e.repository ? e.repository.name : ''}, uris: [${e.uris
+                    .map(u => u.fsPath)
+                    .join(', ')}] }`
+        }
+    })
     private onFileSystemChanged(e: RepositoryFileSystemChangeEvent) {
         void this.triggerChange();
     }
 
+    @debug({
+        args: {
+            e: (e: RepositoryChangeEvent) =>
+                `{ repository: ${e.repository ? e.repository.name : ''}, changes: ${e.changes.join()} }`
+        }
+    })
     private onRepoChanged(e: RepositoryChangeEvent) {
-        Logger.log(`RepositoryNode.onRepoChanged(${e.changes.join()}); triggering node refresh`);
-
         if (e.changed(RepositoryChange.Closed)) {
             this.dispose();
 
@@ -325,6 +340,7 @@ export class RepositoryNode extends SubscribeableViewNode {
         );
     }
 
+    @debug()
     private async updateLastFetched() {
         const prevLastFetched = this._lastFetched;
         this._lastFetched = await this.getLastFetched();

src/views/nodes/viewNode.ts

@@ -1,6 +1,7 @@
 'use strict';
 import { Command, Disposable, Event, TreeItem, TreeViewVisibilityChangeEvent } from 'vscode';
 import { GitUri } from '../../git/gitService';
+import { debug, logName } from '../../system';
 import { RefreshReason, View } from '../viewBase';
 
 export enum ResourceType {
@@ -51,6 +52,11 @@ export interface NamedRef {
 
 export const unknownGitUri = new GitUri();
 
+export interface ViewNode {
+    readonly id?: string;
+}
+
+@logName<ViewNode>((c, name) => `${name}${c.id ? `(${c.id})` : ''}`)
 export abstract class ViewNode {
     constructor(
         uri: GitUri,
@@ -76,6 +82,7 @@ export abstract class ViewNode {
         return undefined;
     }
 
+    @debug()
     refresh(reason?: RefreshReason): void | boolean | Promise<void> | Promise<boolean> {}
 }
 
@@ -124,6 +131,7 @@ export abstract class SubscribeableViewNode extends ViewNode
         this._disposable = Disposable.from(...disposables);
     }
 
+    @debug()
     dispose() {
         this.unsubscribe();
 
@@ -147,12 +155,14 @@ export abstract class SubscribeableViewNode extends ViewNode
         }
     }
 
+    @debug()
     async triggerChange() {
         return this.view.refreshNode(this);
     }
 
     protected abstract async subscribe(): Promise<Disposable | undefined>;
 
+    @debug()
     protected async unsubscribe(): Promise<void> {
         if (this._subscription !== undefined) {
             const subscriptionPromise = this._subscription;
@@ -165,10 +175,12 @@ export abstract class SubscribeableViewNode extends ViewNode
         }
     }
 
+    @debug()
     protected onAutoRefreshChanged() {
         this.onVisibilityChanged({ visible: this.view.visible });
     }
 
+    @debug()
     protected onVisibilityChanged(e: TreeViewVisibilityChangeEvent) {
         void this.ensureSubscription();
 
@@ -177,6 +189,7 @@ export abstract class SubscribeableViewNode extends ViewNode
         }
     }
 
+    @debug()
     async ensureSubscription() {
         // We only need to subscribe if we are visible and if auto-refresh enabled (when supported)
         if (!this.canSubscribe || !this.view.visible || (supportsAutoRefresh(this.view) && !this.view.autoRefresh)) {

src/views/viewBase.ts

@@ -13,6 +13,7 @@ import {
 import { configuration } from '../configuration';
 import { Container } from '../container';
 import { Logger } from '../logger';
+import { debug, log } from '../system';
 import { FileHistoryView } from './fileHistoryView';
 import { LineHistoryView } from './lineHistoryView';
 import { ViewNode } from './nodes';
@@ -112,13 +113,12 @@ export abstract class ViewBase implements TreeDataProvid
         return this._tree !== undefined ? this._tree.visible : false;
     }
 
+    @debug()
     async refresh(reason?: RefreshReason) {
         if (reason === undefined) {
             reason = RefreshReason.Command;
         }
 
-        Logger.log(`View(${this.id}).refresh`, `reason='${reason}'`);
-
         if (this._root !== undefined) {
             await this._root.refresh(reason);
         }
@@ -126,9 +126,10 @@ export abstract class ViewBase implements TreeDataProvid
         this.triggerNodeChange();
     }
 
+    @debug({
+        args: { node: (n: ViewNode) => `${n.constructor.name}${n.id ? `(${n.id})` : ''}` }
+    })
     async refreshNode(node: ViewNode, args?: RefreshNodeCommandArgs) {
-        Logger.log(`View(${this.id}).refreshNode(${(node as { id?: string }).id || ''})`);
-
         if (args !== undefined) {
             if (isPageable(node)) {
                 if (args.maxCount === undefined || args.maxCount === 0) {
@@ -146,6 +147,9 @@ export abstract class ViewBase implements TreeDataProvid
         this.triggerNodeChange(node);
     }
 
+    @log({
+        args: { node: (n: ViewNode) => `${n.constructor.name}${n.id ? `(${n.id})` : ''}` }
+    })
     async reveal(
         node: ViewNode,
         options?: {
@@ -163,6 +167,7 @@ export abstract class ViewBase implements TreeDataProvid
         }
     }
 
+    @log()
     async show() {
         if (this._tree === undefined || this._root === undefined) return;
 
@@ -171,6 +176,9 @@ export abstract class ViewBase implements TreeDataProvid
         return this.reveal(child, { select: false, focus: true });
     }
 
+    @debug({
+        args: { node: (n?: ViewNode) => (n != null ? `${n.constructor.name}${n.id ? `(${n.id})` : ''}` : '') }
+    })
     triggerNodeChange(node?: ViewNode) {
         // Since the root node won't actually refresh, force everything
         this._onDidChangeTreeData.fire(node !== undefined && node !== this._root ? node : undefined);