Fixes logger correlation and other tweaks

src/logger.ts

@@ -12,8 +12,9 @@ const ConsolePrefix = `[${extensionOutputChannelName}]`;
 const isDebuggingRegex = /\bgitlens\b/i;
 
 export interface LogCorrelationContext {
-    correlationId?: number;
-    prefix: string;
+    readonly correlationId?: number;
+    readonly prefix: string;
+    exitDetails?: string;
 }
 
 export class Logger {
@@ -47,18 +48,18 @@ export class Logger {
 
     static debug(message: string, ...params: any[]): void;
     static debug(context: LogCorrelationContext | undefined, message: string, ...params: any[]): void;
-    static debug(callerOrMessage: LogCorrelationContext | string | undefined, ...params: any[]): void {
+    static debug(contextOrMessage: LogCorrelationContext | string | undefined, ...params: any[]): void {
         if (this.level !== LogLevel.Debug && !Logger.isDebugging) return;
 
         let message;
-        if (typeof callerOrMessage === 'string') {
-            message = callerOrMessage;
+        if (typeof contextOrMessage === 'string') {
+            message = contextOrMessage;
         }
         else {
             message = params.shift();
 
-            if (callerOrMessage !== undefined) {
-                message = `${callerOrMessage.prefix} ${message || ''}`;
+            if (contextOrMessage !== undefined) {
+                message = `${contextOrMessage.prefix} ${message || ''}`;
             }
         }
 
@@ -67,24 +68,24 @@ export class Logger {
         }
 
         if (this.output !== undefined && this.level === LogLevel.Debug) {
-            this.output.appendLine(`${this.timestamp} ${message || ''} ${this.toLoggableParams(true, params)}`);
+            this.output.appendLine(`${this.timestamp} ${message || ''}${this.toLoggableParams(true, params)}`);
         }
     }
 
     static error(ex: Error, message?: string, ...params: any[]): void;
     static error(ex: Error, context?: LogCorrelationContext, message?: string, ...params: any[]): void;
-    static error(ex: Error, callerOrMessage: LogCorrelationContext | string | undefined, ...params: any[]): void {
+    static error(ex: Error, contextOrMessage: LogCorrelationContext | string | undefined, ...params: any[]): void {
         if (this.level === LogLevel.Silent && !Logger.isDebugging) return;
 
         let message;
-        if (callerOrMessage === undefined || typeof callerOrMessage === 'string') {
-            message = callerOrMessage;
+        if (contextOrMessage === undefined || typeof contextOrMessage === 'string') {
+            message = contextOrMessage;
         }
         else {
             message = params.shift();
 
-            if (callerOrMessage !== undefined) {
-                message = `${callerOrMessage.prefix} ${message || ''}`;
+            if (contextOrMessage !== undefined) {
+                message = `${contextOrMessage.prefix} ${message || ''}`;
             }
         }
 
@@ -103,7 +104,7 @@ export class Logger {
         }
 
         if (this.output !== undefined && this.level !== LogLevel.Silent) {
-            this.output.appendLine(`${this.timestamp} ${message || ''} ${this.toLoggableParams(false, params)}\n${ex}`);
+            this.output.appendLine(`${this.timestamp} ${message || ''}${this.toLoggableParams(false, params)}\n${ex}`);
         }
 
         // Telemetry.trackException(ex);
@@ -115,20 +116,20 @@ export class Logger {
 
     static log(message: string, ...params: any[]): void;
     static log(context: LogCorrelationContext | undefined, message: string, ...params: any[]): void;
-    static log(callerOrMessage: LogCorrelationContext | string | undefined, ...params: any[]): void {
+    static log(contextOrMessage: LogCorrelationContext | string | undefined, ...params: any[]): void {
         if (this.level !== LogLevel.Verbose && this.level !== LogLevel.Debug && !Logger.isDebugging) {
             return;
         }
 
         let message;
-        if (typeof callerOrMessage === 'string') {
-            message = callerOrMessage;
+        if (typeof contextOrMessage === 'string') {
+            message = contextOrMessage;
         }
         else {
             message = params.shift();
 
-            if (callerOrMessage !== undefined) {
-                message = `${callerOrMessage.prefix} ${message || ''}`;
+            if (contextOrMessage !== undefined) {
+                message = `${contextOrMessage.prefix} ${message || ''}`;
             }
         }
 
@@ -137,26 +138,26 @@ export class Logger {
         }
 
         if (this.output !== undefined && (this.level === LogLevel.Verbose || this.level === LogLevel.Debug)) {
-            this.output.appendLine(`${this.timestamp} ${message || ''} ${this.toLoggableParams(false, params)}`);
+            this.output.appendLine(`${this.timestamp} ${message || ''}${this.toLoggableParams(false, params)}`);
         }
     }
 
     static logWithDebugParams(message: string, ...params: any[]): void;
     static logWithDebugParams(context: LogCorrelationContext | undefined, message: string, ...params: any[]): void;
-    static logWithDebugParams(callerOrMessage: LogCorrelationContext | string | undefined, ...params: any[]): void {
+    static logWithDebugParams(contextOrMessage: LogCorrelationContext | string | undefined, ...params: any[]): void {
         if (this.level !== LogLevel.Verbose && this.level !== LogLevel.Debug && !Logger.isDebugging) {
             return;
         }
 
         let message;
-        if (typeof callerOrMessage === 'string') {
-            message = callerOrMessage;
+        if (typeof contextOrMessage === 'string') {
+            message = contextOrMessage;
         }
         else {
             message = params.shift();
 
-            if (callerOrMessage !== undefined) {
-                message = `${callerOrMessage.prefix} ${message || ''}`;
+            if (contextOrMessage !== undefined) {
+                message = `${contextOrMessage.prefix} ${message || ''}`;
             }
         }
 
@@ -165,24 +166,24 @@ export class Logger {
         }
 
         if (this.output !== undefined && (this.level === LogLevel.Verbose || this.level === LogLevel.Debug)) {
-            this.output.appendLine(`${this.timestamp} ${message || ''} ${this.toLoggableParams(true, params)}`);
+            this.output.appendLine(`${this.timestamp} ${message || ''}${this.toLoggableParams(true, params)}`);
         }
     }
 
     static warn(message: string, ...params: any[]): void;
     static warn(context: LogCorrelationContext | undefined, message: string, ...params: any[]): void;
-    static warn(callerOrMessage: LogCorrelationContext | string | undefined, ...params: any[]): void {
+    static warn(contextOrMessage: LogCorrelationContext | string | undefined, ...params: any[]): void {
         if (this.level === LogLevel.Silent && !Logger.isDebugging) return;
 
         let message;
-        if (typeof callerOrMessage === 'string') {
-            message = callerOrMessage;
+        if (typeof contextOrMessage === 'string') {
+            message = contextOrMessage;
         }
         else {
             message = params.shift();
 
-            if (callerOrMessage !== undefined) {
-                message = `${callerOrMessage.prefix} ${message || ''}`;
+            if (contextOrMessage !== undefined) {
+                message = `${contextOrMessage.prefix} ${message || ''}`;
             }
         }
 
@@ -191,7 +192,7 @@ export class Logger {
         }
 
         if (this.output !== undefined && this.level !== LogLevel.Silent) {
-            this.output.appendLine(`${this.timestamp} ${message || ''} ${this.toLoggableParams(false, params)}`);
+            this.output.appendLine(`${this.timestamp} ${message || ''}${this.toLoggableParams(false, params)}`);
         }
     }
 
@@ -253,7 +254,7 @@ export class Logger {
         }
 
         const loggableParams = params.map(p => this.toLoggable(p)).join(', ');
-        return loggableParams || '';
+        return ` \u2014 ${loggableParams}` || '';
     }
 
     private static _isDebugging: boolean | undefined;

src/system/decorators/log.ts

@@ -15,6 +15,9 @@ export function getCorrelationId() {
 }
 
 function getNextCorrelationId() {
+    if (correlationCounter === Number.MAX_SAFE_INTEGER) {
+        correlationCounter = 0;
+    }
     return ++correlationCounter;
 }
 
@@ -27,11 +30,11 @@ function setCorrelationContext(correlationId: number, context: LogCorrelationCon
 }
 
 export interface LogContext<T> {
-    prefix: string;
-    name: string;
+    id: number;
     instance: T;
     instanceName: string;
-    id?: number;
+    name: string;
+    prefix: string;
 }
 
 export const LogInstanceNameFn = Symbol('logInstanceNameFn');
@@ -51,6 +54,7 @@ export function debug(
         exit?(result: any): string;
         prefix?(context: LogContext<T>, ...args: any[]): string;
         sanitize?(key: string, value: any): any;
+        singleLine?: boolean;
         timed?: boolean;
     } = { timed: true }
 ) {
@@ -88,6 +92,8 @@ export function log(
         const parameters = Functions.getParameters(fn);
 
         descriptor.value = function(this: any, ...args: any[]) {
+            const correlationId = getNextCorrelationId();
+
             if (
                 (Logger.level !== LogLevel.Debug && !(Logger.level === LogLevel.Verbose && !options.debug)) ||
                 (typeof options.condition === 'function' && !options.condition(...args))
@@ -106,31 +112,32 @@ export function log(
                 instanceName = '';
             }
 
-            let correlationId: number | undefined;
-            let prefix: string;
-            if ((options.correlate || options.timed) && !options.singleLine) {
-                correlationId = getNextCorrelationId();
-                prefix = `[${correlationId.toString(16)}] ${instanceName ? `${instanceName}.` : ''}${key}`;
-            }
-            else {
-                prefix = `${instanceName ? `${instanceName}.` : ''}${key}`;
+            let { correlate } = options;
+            if (!correlate && options.timed) {
+                correlate = true;
             }
 
+            let prefix = `${correlate ? `[${correlationId.toString(16)}] ` : ''}${
+                instanceName ? `${instanceName}.` : ''
+            }${key}`;
+
             if (options.prefix != null) {
                 prefix = options.prefix(
                     {
-                        prefix: prefix,
+                        id: correlationId,
                         instance: this,
-                        name: key,
                         instanceName: instanceName,
-                        id: correlationId
+                        name: key,
+                        prefix: prefix
                     } as LogContext<T>,
                     ...args
                 );
             }
 
-            if (correlationId !== undefined) {
-                setCorrelationContext(correlationId, { correlationId: correlationId, prefix: prefix });
+            let correlationContext: LogCorrelationContext | undefined;
+            if (correlate) {
+                correlationContext = { correlationId: correlationId, prefix: prefix };
+                setCorrelationContext(correlationId, correlationContext);
             }
 
             const enter = options.enter != null ? options.enter(...args) : '';
@@ -180,9 +187,31 @@ export function log(
 
                 const logError = (ex: Error) => {
                     const timing = start !== undefined ? ` \u2022 ${Strings.getDurationMilliseconds(start)} ms` : '';
-                    Logger.error(ex, prefix, `failed${timing}${options.singleLine ? `${enter}${loggableParams}` : ''}`);
+                    if (options.singleLine) {
+                        Logger.error(
+                            ex,
+                            `${prefix}${enter}`,
+                            `failed${
+                                correlationContext !== undefined && correlationContext.exitDetails
+                                    ? correlationContext.exitDetails
+                                    : ''
+                            }${timing}`,
+                            loggableParams
+                        );
+                    }
+                    else {
+                        Logger.error(
+                            ex,
+                            prefix,
+                            `failed${
+                                correlationContext !== undefined && correlationContext.exitDetails
+                                    ? correlationContext.exitDetails
+                                    : ''
+                            }${timing}`
+                        );
+                    }
 
-                    if (correlationId !== undefined) {
+                    if (correlate) {
                         clearCorrelationContext(correlationId);
                     }
                 };
@@ -213,17 +242,37 @@ export function log(
 
                     if (options.singleLine) {
                         if (!options.debug) {
-                            Logger.logWithDebugParams(`${prefix} ${enter}${exit}${timing}`, loggableParams);
+                            Logger.logWithDebugParams(
+                                `${prefix}${enter} ${exit}${
+                                    correlationContext !== undefined && correlationContext.exitDetails
+                                        ? correlationContext.exitDetails
+                                        : ''
+                                }${timing}`,
+                                loggableParams
+                            );
                         }
                         else {
-                            logFn(prefix, `${enter}${exit}${timing}`, loggableParams);
+                            logFn(
+                                `${prefix}${enter} ${exit}${
+                                    correlationContext !== undefined && correlationContext.exitDetails
+                                        ? correlationContext.exitDetails
+                                        : ''
+                                }${timing}`,
+                                loggableParams
+                            );
                         }
                     }
                     else {
-                        logFn(prefix, `${exit}${timing}`);
+                        logFn(
+                            `${prefix} ${exit}${
+                                correlationContext !== undefined && correlationContext.exitDetails
+                                    ? correlationContext.exitDetails
+                                    : ''
+                            }${timing}`
+                        );
                     }
 
-                    if (correlationId !== undefined) {
+                    if (correlate) {
                         clearCorrelationContext(correlationId);
                     }
                 };