diff --git a/src/git/git.ts b/src/git/git.ts index 30bf0f6..3587d84 100644 --- a/src/git/git.ts +++ b/src/git/git.ts @@ -160,19 +160,24 @@ export async function git(options: GitCommandOptio } finally { pendingCommands.delete(command); - const duration = `${Strings.getDurationMilliseconds(start)} ms ${waiting ? '(waited) ' : emptyStr}`; - if (exception !== undefined) { - Logger.warn( + const duration = Strings.getDurationMilliseconds(start); + const elapsed = `${duration} ms ${waiting ? '(waited) ' : emptyStr}`; + if (exception != null) { + Logger.error( + '', `[${runOpts.cwd}] Git ${(exception.message || exception.toString() || emptyStr) .trim() .replace(/fatal: /g, '') - .replace(/\r?\n|\r/g, ` ${GlyphChars.Dot} `)} ${GlyphChars.Dot} ${duration}`, + .replace(/\r?\n|\r/g, ` ${GlyphChars.Dot} `)} ${GlyphChars.Dot} ${elapsed}`, ); + } else if (duration > Logger.slowCallWarningThreshold) { + Logger.warn(`${gitCommand} ${GlyphChars.Dot} ${elapsed} (slow)`); } else { - Logger.log(`${gitCommand} ${GlyphChars.Dot} ${duration}`); + Logger.log(`${gitCommand} ${GlyphChars.Dot} ${elapsed}`); } Logger.logGitCommand( - `${gitCommand} ${GlyphChars.Dot} ${exception !== undefined ? 'FAILED ' : emptyStr}${duration}`, + `${gitCommand} ${GlyphChars.Dot} ${exception !== undefined ? 'FAILED ' : emptyStr}${elapsed}`, + duration, exception, ); } diff --git a/src/logger.ts b/src/logger.ts index d8f19fd..bd487de 100644 --- a/src/logger.ts +++ b/src/logger.ts @@ -33,6 +33,8 @@ export interface LogCorrelationContext { } export class Logger { + static readonly slowCallWarningThreshold = 500; + private static output: OutputChannel | undefined; private static customLoggableFn: ((o: object) => string | undefined) | undefined; @@ -152,30 +154,6 @@ export class Logger { this.output.appendLine(`${this.timestamp} ${message ?? emptyStr}${this.toLoggableParams(false, params)}`); } - static logWithDebugParams(message: string, ...params: any[]): void; - static logWithDebugParams(context: LogCorrelationContext | undefined, message: string, ...params: any[]): void; - static logWithDebugParams(contextOrMessage: LogCorrelationContext | string | undefined, ...params: any[]): void { - if (this.level < OrderedLevel.Info && !this.isDebugging) return; - - let message; - if (typeof contextOrMessage === 'string') { - message = contextOrMessage; - } else { - message = params.shift(); - - if (contextOrMessage != null) { - message = `${contextOrMessage.prefix} ${message ?? emptyStr}`; - } - } - - if (this.isDebugging) { - console.log(this.timestamp, consolePrefix, message ?? emptyStr, ...params); - } - - if (this.output == null || this.level < OrderedLevel.Info) return; - this.output.appendLine(`${this.timestamp} ${message ?? emptyStr}${this.toLoggableParams(true, params)}`); - } - static warn(message: string, ...params: any[]): void; static warn(context: LogCorrelationContext | undefined, message: string, ...params: any[]): void; static warn(contextOrMessage: LogCorrelationContext | string | undefined, ...params: any[]): void { @@ -267,12 +245,14 @@ export class Logger { static gitOutput: OutputChannel | undefined; - static logGitCommand(command: string, ex?: Error): void { + static logGitCommand(command: string, duration: number, ex?: Error): void { if (this.level < OrderedLevel.Debug && !this.isDebugging) return; if (this.isDebugging) { if (ex != null) { console.error(this.timestamp, gitConsolePrefix, command ?? emptyStr, ex); + } else if (duration > Logger.slowCallWarningThreshold) { + console.warn(this.timestamp, gitConsolePrefix, command ?? emptyStr); } else { console.log(this.timestamp, gitConsolePrefix, command ?? emptyStr); } diff --git a/src/system/decorators/log.ts b/src/system/decorators/log.ts index 03f45a4..024d0d3 100644 --- a/src/system/decorators/log.ts +++ b/src/system/decorators/log.ts @@ -105,6 +105,7 @@ export function log any>( const logFn = (options.debug ? Logger.debug.bind(Logger) : Logger.log.bind(Logger)) as | typeof Logger.debug | typeof Logger.log; + const warnFn = Logger.warn.bind(Logger); return (target: any, key: string, descriptor: PropertyDescriptor & Record) => { let fn: Function | undefined; @@ -200,11 +201,12 @@ export function log any>( }).join(', '); if (!options.singleLine) { - if (!options.debug) { - Logger.logWithDebugParams(`${prefix}${enter}`, loggableParams); - } else { - logFn(`${prefix}${enter}`, loggableParams); - } + logFn( + `${prefix}${enter}`, + !options.debug && !Logger.enabled(LogLevel.Debug) && !Logger.isDebugging + ? emptyStr + : loggableParams, + ); } } @@ -246,7 +248,22 @@ export function log any>( } const logResult = (r: any) => { - const timing = start !== undefined ? ` \u2022 ${getDurationMilliseconds(start)} ms` : emptyStr; + let exitLogFn; + let timing; + if (start != null) { + const duration = getDurationMilliseconds(start); + if (duration > Logger.slowCallWarningThreshold) { + exitLogFn = warnFn; + timing = ` \u2022 ${duration} ms (slow)`; + } else { + exitLogFn = logFn; + timing = ` \u2022 ${duration} ms`; + } + } else { + timing = emptyStr; + exitLogFn = logFn; + } + let exit; if (options.exit != null) { try { @@ -259,23 +276,16 @@ export function log any>( } if (options.singleLine) { - if (!options.debug) { - Logger.logWithDebugParams( - `${prefix}${enter} ${exit}${ - correlationContext?.exitDetails ? correlationContext.exitDetails : emptyStr - }${timing}`, - loggableParams, - ); - } else { - logFn( - `${prefix}${enter} ${exit}${ - correlationContext?.exitDetails ? correlationContext.exitDetails : emptyStr - }${timing}`, - loggableParams, - ); - } + exitLogFn( + `${prefix}${enter} ${exit}${ + correlationContext?.exitDetails ? correlationContext.exitDetails : emptyStr + }${timing}`, + !options.debug && !Logger.enabled(LogLevel.Debug) && !Logger.isDebugging + ? emptyStr + : loggableParams, + ); } else { - logFn( + exitLogFn( `${prefix} ${exit}${ correlationContext?.exitDetails ? correlationContext.exitDetails : emptyStr }${timing}`,