diff --git a/src/client/common/logger.ts b/src/client/common/logger.ts index f43a633ffd45..d332dd6028e5 100644 --- a/src/client/common/logger.ts +++ b/src/client/common/logger.ts @@ -1,10 +1,10 @@ +// These are all just temporary aliases, for backward compatibility +// and to avoid churn. export { - // aliases: - // (temporarily for backward compatibility and to avoid churn) traceDecorators, - traceError, - traceInfo, - traceVerbose, - traceWarning -} from '../logging/_trace'; -export { TraceOptions as LogOptions } from '../logging/types'; + logError as traceError, + logInfo as traceInfo, + logVerbose as traceVerbose, + logWarning as traceWarning +} from '../logging'; +export { TraceOptions as LogOptions } from '../logging/trace'; diff --git a/src/client/common/utils/async.ts b/src/client/common/utils/async.ts index 8ecd281a862d..030ac00b7c10 100644 --- a/src/client/common/utils/async.ts +++ b/src/client/common/utils/async.ts @@ -27,6 +27,16 @@ export async function waitForPromise(promise: Promise, timeout: number): P }); } +// tslint:disable-next-line: no-any +export function isThenable(v: any): v is Thenable { + return typeof v?.then === 'function'; +} + +// tslint:disable-next-line: no-any +export function isPromise(v: any): v is Promise { + return typeof v?.then === 'function' && typeof v?.catch === 'function'; +} + //====================== // Deferred diff --git a/src/client/common/utils/decorators.ts b/src/client/common/utils/decorators.ts index e0e85bfded1b..512f31e65e19 100644 --- a/src/client/common/utils/decorators.ts +++ b/src/client/common/utils/decorators.ts @@ -8,6 +8,7 @@ import { traceError, traceVerbose } from '../logger'; import { Resource } from '../types'; import { createDeferred, Deferred } from './async'; import { getCacheKeyFromFunctionArgs, getGlobalCacheStore, InMemoryInterpreterSpecificCache } from './cacheUtils'; +import { TraceInfo, tracing } from './misc'; // tslint:disable-next-line:no-require-imports no-var-requires const _debounce = require('lodash/debounce') as typeof import('lodash/debounce'); @@ -225,3 +226,37 @@ export function displayProgress(title: string, location = ProgressLocation.Windo }; }; } + +// Information about a function/method call. +export type CallInfo = { + kind: string; // "Class", etc. + name: string; + // tslint:disable-next-line:no-any + args: any[]; +}; + +// Return a decorator that traces the decorated function. +export function trace(log: (c: CallInfo, t: TraceInfo) => void) { + // tslint:disable-next-line:no-function-expression no-any + return function (_: Object, __: string, descriptor: TypedPropertyDescriptor) { + const originalMethod = descriptor.value; + // tslint:disable-next-line:no-function-expression no-any + descriptor.value = function (...args: any[]) { + const call = { + kind: 'Class', + name: _ && _.constructor ? _.constructor.name : '', + args + }; + // tslint:disable-next-line:no-this-assignment no-invalid-this + const scope = this; + return tracing( + // "log()" + (t) => log(call, t), + // "run()" + () => originalMethod.apply(scope, args) + ); + }; + + return descriptor; + }; +} diff --git a/src/client/common/utils/misc.ts b/src/client/common/utils/misc.ts index 1f21921fe6f6..972e197d3eba 100644 --- a/src/client/common/utils/misc.ts +++ b/src/client/common/utils/misc.ts @@ -4,6 +4,8 @@ import { Uri } from 'vscode'; import { InterpreterUri } from '../installer/types'; import { IAsyncDisposable, IDisposable, Resource } from '../types'; +import { isPromise } from './async'; +import { StopWatch } from './stopWatch'; // tslint:disable-next-line:no-empty export function noop() {} @@ -38,6 +40,46 @@ export async function usingAsync( } } +// Information about a traced function/method call. +export type TraceInfo = { + elapsed: number; // milliseconds + // Either returnValue or err will be set. + // tslint:disable-next-line:no-any + returnValue?: any; + err?: Error; +}; + +// Call run(), call log() with the trace info, and return the result. +export function tracing(log: (t: TraceInfo) => void, run: () => T): T { + const timer = new StopWatch(); + try { + // tslint:disable-next-line:no-invalid-this no-use-before-declare no-unsafe-any + const result = run(); + + // If method being wrapped returns a promise then wait for it. + if (isPromise(result)) { + // tslint:disable-next-line:prefer-type-cast + (result as Promise) + .then((data) => { + log({ elapsed: timer.elapsedTime, returnValue: data }); + return data; + }) + .catch((ex) => { + log({ elapsed: timer.elapsedTime, err: ex }); + // tslint:disable-next-line:no-suspicious-comment + // TODO(GH-11645) Re-throw the error like we do + // in the non-Promise case. + }); + } else { + log({ elapsed: timer.elapsedTime, returnValue: result }); + } + return result; + } catch (ex) { + log({ elapsed: timer.elapsedTime, err: ex }); + throw ex; + } +} + /** * Checking whether something is a Resource (Uri/undefined). * Using `instanceof Uri` doesn't always work as the object is not an instance of Uri (at least not in tests). diff --git a/src/client/logging/_console.ts b/src/client/logging/_console.ts deleted file mode 100644 index a628c94e852b..000000000000 --- a/src/client/logging/_console.ts +++ /dev/null @@ -1,74 +0,0 @@ -// Copyright (c) Microsoft Corporation. All rights reserved. -// Licensed under the MIT License. -'use strict'; - -// tslint:disable:no-console no-any - -import { ConsoleStreams, LogLevel } from './types'; - -const logMethods = { - log: Symbol.for('log'), - info: Symbol.for('info'), - error: Symbol.for('error'), - debug: Symbol.for('debug'), - warn: Symbol.for('warn') -}; - -// Log a message based on "args" to the given console "stream". -export function logToConsole(stream: ConsoleStreams, ...args: any[]) { - if (['info', 'error', 'warn', 'log', 'debug'].indexOf(stream) === -1) { - stream = 'log'; - } - // Further below we monkeypatch the console.log, etc methods. - const fn = (console as any)[logMethods[stream]] || console[stream] || console.log; - fn(...args); -} - -/** - * What we're doing here is monkey patching the console.log so we can - * send everything sent to console window into our logs. This is only - * required when we're directly writing to `console.log` or not using - * our `winston logger`. This is something we'd generally turn on, only - * on CI so we can see everything logged to the console window - * (via the logs). - */ -export function monkeypatchConsole(logToFile: (logLevel: LogLevel, ...args: any[]) => void) { - // Keep track of the original functions before we monkey patch them. - // Using symbols guarantee the properties will be unique & prevents clashing with names other code/library may create or have created. - (console as any)[logMethods.log] = console.log; - (console as any)[logMethods.info] = console.info; - (console as any)[logMethods.error] = console.error; - (console as any)[logMethods.debug] = console.debug; - (console as any)[logMethods.warn] = console.warn; - - // tslint:disable-next-line: no-function-expression - console.log = function () { - const args = Array.prototype.slice.call(arguments); - logToConsole('log', ...args); - logToFile(LogLevel.Information, ...args); - }; - // tslint:disable-next-line: no-function-expression - console.info = function () { - const args = Array.prototype.slice.call(arguments); - logToConsole('info', ...args); - logToFile(LogLevel.Information, ...args); - }; - // tslint:disable-next-line: no-function-expression - console.warn = function () { - const args = Array.prototype.slice.call(arguments); - logToConsole('warn', ...args); - logToFile(LogLevel.Warning, ...args); - }; - // tslint:disable-next-line: no-function-expression - console.error = function () { - const args = Array.prototype.slice.call(arguments); - logToConsole('error', ...args); - logToFile(LogLevel.Error, ...args); - }; - // tslint:disable-next-line: no-function-expression - console.debug = function () { - const args = Array.prototype.slice.call(arguments); - logToConsole('debug', ...args); - logToFile(LogLevel.Information, ...args); - }; -} diff --git a/src/client/logging/_global.ts b/src/client/logging/_global.ts new file mode 100644 index 000000000000..6577725ef56d --- /dev/null +++ b/src/client/logging/_global.ts @@ -0,0 +1,157 @@ +// Copyright (c) Microsoft Corporation. All rights reserved. +// Licensed under the MIT License. +'use strict'; + +import { isCI, isTestExecution } from '../common/constants'; +import { CallInfo } from '../common/utils/decorators'; +import { LogLevel } from './levels'; +import { configureLogger, createLogger, ILogger, LoggerConfig, logToAll } from './logger'; +import { createTracingDecorator, LogInfo, TraceOptions, tracing as _tracing } from './trace'; +import { Arguments } from './util'; + +const globalLogger = createLogger(); +initialize(); + +/** + * Initialize the logger. + * + * For console we do two things here: + * - Anything written to the logger will be displayed in the console + * window as well This is the behavior of the extension when running + * it. When running tests on CI, we might not want this behavior, as + * it'll pollute the test output with logging (as mentioned this is + * optional). Messages logged using our logger will be prefixed with + * `Python Extension: ....` for console window. This way, its easy + * to identify messages specific to the python extension. + * - Monkey patch the console.log and similar methods to send messages + * to the file logger. When running UI tests or similar, and we want + * to see everything that was dumped into `console window`, then we + * need to hijack the console logger. To do this we need to monkey + * patch the console methods. This is optional (generally done when + * running tests on CI). + * + * For the logfile: + * - we send all logging output to a log file. We log to the file + * only if a file has been specified as an env variable. Currently + * this is setup on CI servers. + */ +function initialize() { + const config: LoggerConfig = {}; + let nonConsole = false; + + // Do not log to console if running tests and we're not + // asked to do so. + if (!isTestExecution() || process.env.VSC_PYTHON_FORCE_LOGGING) { + config.console = {}; + // In CI there's no need for the label. + if (!isCI) { + config.console.label = 'Python Extension:'; + } + } + if (process.env.VSC_PYTHON_LOG_FILE) { + config.file = { + logfile: process.env.VSC_PYTHON_LOG_FILE + }; + nonConsole = true; + } + configureLogger(globalLogger, config); + + if (isCI && nonConsole) { + delete config.console; + // Send console.*() to the non-console loggers. + monkeypatchConsole( + // This is a separate logger that matches our config but + // does not do any console logging. + createLogger(config) + ); + } +} + +// Emit a log message derived from the args to all enabled transports. +export function log(logLevel: LogLevel, ...args: Arguments) { + logToAll([globalLogger], logLevel, args); +} + +// tslint:disable-next-line:no-any +export function logVerbose(...args: any[]) { + log(LogLevel.Info, ...args); +} + +// tslint:disable-next-line:no-any +export function logError(...args: any[]) { + log(LogLevel.Error, ...args); +} + +// tslint:disable-next-line:no-any +export function logInfo(...args: any[]) { + log(LogLevel.Info, ...args); +} + +// tslint:disable-next-line:no-any +export function logWarning(...args: any[]) { + log(LogLevel.Warn, ...args); +} + +// This is like a "context manager" that logs tracing info. +export function tracing(info: LogInfo, run: () => T, call?: CallInfo): T { + return _tracing([globalLogger], info, run, call); +} + +export namespace traceDecorators { + const DEFAULT_OPTS: TraceOptions = TraceOptions.Arguments | TraceOptions.ReturnValue; + + export function verbose(message: string, opts: TraceOptions = DEFAULT_OPTS) { + return createTracingDecorator([globalLogger], { message, opts }); + } + export function error(message: string) { + const opts = DEFAULT_OPTS; + const level = LogLevel.Error; + return createTracingDecorator([globalLogger], { message, opts, level }); + } + export function info(message: string) { + const opts = TraceOptions.None; + return createTracingDecorator([globalLogger], { message, opts }); + } + export function warn(message: string) { + const opts = DEFAULT_OPTS; + const level = LogLevel.Warn; + return createTracingDecorator([globalLogger], { message, opts, level }); + } +} + +// Ensure that the console functions are bound before monkeypatching. +import './transports'; + +/** + * What we're doing here is monkey patching the console.log so we can + * send everything sent to console window into our logs. This is only + * required when we're directly writing to `console.log` or not using + * our `winston logger`. This is something we'd generally turn on, only + * on CI so we can see everything logged to the console window + * (via the logs). + */ +function monkeypatchConsole(logger: ILogger) { + // The logging "streams" (methods) of the node console. + const streams = ['log', 'error', 'warn', 'info', 'debug', 'trace']; + const levels: { [key: string]: LogLevel } = { + error: LogLevel.Error, + warn: LogLevel.Warn + }; + // tslint:disable-next-line:no-any + const consoleAny: any = console; + for (const stream of streams) { + // Using symbols guarantee the properties will be unique & prevents + // clashing with names other code/library may create or have created. + // We could use a closure but it's a bit trickier. + const sym = Symbol.for(stream); + consoleAny[sym] = consoleAny[stream]; + // tslint:disable-next-line: no-function-expression + consoleAny[stream] = function () { + const args = Array.prototype.slice.call(arguments); + const fn = consoleAny[sym]; + fn(...args); + const level = levels[stream] || LogLevel.Info; + logToAll([logger], level, args); + }; + } +} diff --git a/src/client/logging/_trace.ts b/src/client/logging/_trace.ts deleted file mode 100644 index fca65c199735..000000000000 --- a/src/client/logging/_trace.ts +++ /dev/null @@ -1,110 +0,0 @@ -// Copyright (c) Microsoft Corporation. All rights reserved. -// Licensed under the MIT License. -'use strict'; - -// tslint:disable:no-any - -import { StopWatch } from '../common/utils/stopWatch'; -import { sendTelemetryEvent } from '../telemetry'; -import { _log as log } from './logger'; -import { LogLevel, TraceOptions } from './types'; -import { argsToLogString, returnValueToLogString } from './util'; - -export function traceVerbose(...args: any[]) { - log(LogLevel.Information, ...args); -} - -export function traceError(...args: any[]) { - log(LogLevel.Error, ...args); -} - -export function traceInfo(...args: any[]) { - log(LogLevel.Information, ...args); -} - -export function traceWarning(...args: any[]) { - log(LogLevel.Warning, ...args); -} - -export namespace traceDecorators { - export function verbose(message: string, opts: TraceOptions = TraceOptions.Arguments | TraceOptions.ReturnValue) { - return trace(message, opts); - } - export function error(message: string) { - return trace(message, TraceOptions.Arguments | TraceOptions.ReturnValue, LogLevel.Error); - } - export function info(message: string) { - return trace(message); - } - export function warn(message: string) { - return trace(message, TraceOptions.Arguments | TraceOptions.ReturnValue, LogLevel.Warning); - } -} - -function trace(message: string, opts: TraceOptions = TraceOptions.None, logLevel?: LogLevel) { - // tslint:disable-next-line:no-function-expression no-any - return function (_: Object, __: string, descriptor: TypedPropertyDescriptor) { - const originalMethod = descriptor.value; - // tslint:disable-next-line:no-function-expression no-any - descriptor.value = function (...args: any[]) { - const className = _ && _.constructor ? _.constructor.name : ''; - // tslint:disable-next-line:no-any - function writeSuccess(elapsedTime: number, returnValue: any) { - if (logLevel === LogLevel.Error) { - return; - } - writeToLog(elapsedTime, returnValue); - } - function writeError(elapsedTime: number, ex: Error) { - writeToLog(elapsedTime, undefined, ex); - } - // tslint:disable-next-line:no-any - function writeToLog(elapsedTime: number, returnValue?: any, ex?: Error) { - const messagesToLog = [message]; - messagesToLog.push( - `Class name = ${className}, completed in ${elapsedTime}ms, has a ${ - returnValue ? 'truthy' : 'falsy' - } return value` - ); - if ((opts & TraceOptions.Arguments) === TraceOptions.Arguments) { - messagesToLog.push(argsToLogString(args)); - } - if ((opts & TraceOptions.ReturnValue) === TraceOptions.ReturnValue) { - messagesToLog.push(returnValueToLogString(returnValue)); - } - if (ex) { - log(LogLevel.Error, messagesToLog.join(', '), ex); - sendTelemetryEvent('ERROR' as any, undefined, undefined, ex); - } else { - log(LogLevel.Information, messagesToLog.join(', ')); - } - } - const timer = new StopWatch(); - try { - // tslint:disable-next-line:no-invalid-this no-use-before-declare no-unsafe-any - const result = originalMethod.apply(this, args); - // If method being wrapped returns a promise then wait for it. - // tslint:disable-next-line:no-unsafe-any - if (result && typeof result.then === 'function' && typeof result.catch === 'function') { - // tslint:disable-next-line:prefer-type-cast - (result as Promise) - .then((data) => { - writeSuccess(timer.elapsedTime, data); - return data; - }) - .catch((ex) => { - writeError(timer.elapsedTime, ex); - }); - } else { - writeSuccess(timer.elapsedTime, result); - } - return result; - } catch (ex) { - writeError(timer.elapsedTime, ex); - throw ex; - } - }; - - return descriptor; - }; -} diff --git a/src/client/logging/formatters.ts b/src/client/logging/formatters.ts index 1867186d09c2..b3dd4e52761f 100644 --- a/src/client/logging/formatters.ts +++ b/src/client/logging/formatters.ts @@ -3,28 +3,47 @@ 'use strict'; import { format } from 'winston'; -import { FormatterOptions } from './types'; +import { getLevel, LogLevel, LogLevelName } from './levels'; const TIMESTAMP = 'YYYY-MM-DD HH:mm:ss'; -// Return a consistent representation of the given log level. -// +// Knobs used when creating a formatter. +export type FormatterOptions = { + label?: string; +}; + // Pascal casing is used so log files get highlighted when viewing // in VSC and other editors. -function normalizeLevel(level: string): string { - return `${level.substring(0, 1).toUpperCase()}${level.substring(1)}`; +const formattedLogLevels: { [K in LogLevel]: string } = { + [LogLevel.Error]: 'Error', + [LogLevel.Warn]: 'Warn', + [LogLevel.Info]: 'Info', + [LogLevel.Debug]: 'Debug', + [LogLevel.Trace]: 'Trace' +}; + +// Return a consistent representation of the given log level. +function normalizeLevel(name: LogLevelName): string { + const level = getLevel(name); + if (level) { + const norm = formattedLogLevels[level]; + if (norm) { + return norm; + } + } + return `${name.substring(0, 1).toUpperCase()}${name.substring(1).toLowerCase()}`; } // Return a log entry that can be emitted as-is. -function formatMessage(level: string, timestamp: string, message: string): string { - level = normalizeLevel(level); - return `${level} ${timestamp}: ${message}`; +function formatMessage(level: LogLevelName, timestamp: string, message: string): string { + const levelFormatted = normalizeLevel(level); + return `${levelFormatted} ${timestamp}: ${message}`; } // Return a log entry that can be emitted as-is. -function formatLabeledMessage(level: string, timestamp: string, label: string, message: string): string { - level = normalizeLevel(level); - return `${level} ${label} ${timestamp}: ${message}`; +function formatLabeledMessage(level: LogLevelName, timestamp: string, label: string, message: string): string { + const levelFormatted = normalizeLevel(level); + return `${levelFormatted} ${label} ${timestamp}: ${message}`; } // Return a minimal format object that can be used with a "winston" @@ -33,8 +52,8 @@ function getMinimalFormatter() { return format.combine( format.timestamp({ format: TIMESTAMP }), format.printf( - // a minimal message - ({ level, message, timestamp }) => formatMessage(level, timestamp, message) + // This relies on the timestamp formatter we added above: + ({ level, message, timestamp }) => formatMessage(level as LogLevelName, timestamp, message) ) ); } @@ -46,8 +65,9 @@ function getLabeledFormatter(label_: string) { format.label({ label: label_ }), format.timestamp({ format: TIMESTAMP }), format.printf( - // mostly a minimal message - ({ level, message, label, timestamp }) => formatLabeledMessage(level, timestamp, label, message) + // This relies on the label and timestamp formatters we added above: + ({ level, message, label, timestamp }) => + formatLabeledMessage(level as LogLevelName, timestamp, label, message) ) ); } diff --git a/src/client/logging/index.ts b/src/client/logging/index.ts index 6da41c569a13..19dc23d0bfa6 100644 --- a/src/client/logging/index.ts +++ b/src/client/logging/index.ts @@ -5,9 +5,10 @@ export { // aliases // (for convenience) + logError, + logInfo, + logVerbose, + logWarning, traceDecorators, - traceError, - traceInfo, - traceVerbose, - traceWarning -} from './_trace'; + tracing +} from './_global'; diff --git a/src/client/logging/levels.ts b/src/client/logging/levels.ts new file mode 100644 index 000000000000..d857946a6c75 --- /dev/null +++ b/src/client/logging/levels.ts @@ -0,0 +1,100 @@ +// Copyright (c) Microsoft Corporation. All rights reserved. +// Licensed under the MIT License. +'use strict'; + +import * as winston from 'winston'; + +//====================== +// Our custom log levels + +export enum LogLevel { + // Larger numbers are higher priority. + Error = 40, + Warn = 30, + Info = 20, + Debug = 10, + Trace = 5 +} +export type LogLevelName = 'ERROR' | 'WARNING' | 'INFORMATION' | 'DEBUG' | 'DEBUG-TRACE'; +const logLevelMap: { [K in LogLevel]: LogLevelName } = { + [LogLevel.Error]: 'ERROR', + [LogLevel.Warn]: 'WARNING', + [LogLevel.Info]: 'INFORMATION', + [LogLevel.Debug]: 'DEBUG', + [LogLevel.Trace]: 'DEBUG-TRACE' +}; +// This can be used for winston.LoggerOptions.levels. +export const configLevels: winston.config.AbstractConfigSetLevels = { + ERROR: 0, + WARNING: 1, + INFORMATION: 2, + DEBUG: 4, + 'DEBUG-TRACE': 5 +}; + +//====================== +// Other log levels + +// The level names from winston/config.npm. +// See: https://www.npmjs.com/package/winston#logging-levels +type NPMLogLevelName = 'error' | 'warn' | 'info' | 'verbose' | 'debug' | 'silly'; +const npmLogLevelMap: { [K in LogLevel]: NPMLogLevelName } = { + [LogLevel.Error]: 'error', + [LogLevel.Warn]: 'warn', + [LogLevel.Info]: 'info', + [LogLevel.Debug]: 'debug', + [LogLevel.Trace]: 'silly' +}; + +//====================== +// lookup functions + +// Convert from LogLevel enum to the proper level name. +export function resolveLevelName( + level: LogLevel, + // Default to configLevels. + levels?: winston.config.AbstractConfigSetLevels +): string | undefined { + if (levels === undefined) { + return getLevelName(level); + } else if (levels === configLevels) { + return getLevelName(level); + } else if (levels === winston.config.npm.levels) { + return npmLogLevelMap[level]; + } else { + return undefined; + } +} +export function getLevelName(level: LogLevel): LogLevelName | undefined { + return logLevelMap[level]; +} + +// Convert from a level name to the actual level. +export function resolveLevel( + levelName: string, + // Default to configLevels. + levels?: winston.config.AbstractConfigSetLevels +): LogLevel | undefined { + let levelMap: { [K in LogLevel]: string }; + if (levels === undefined) { + levelMap = logLevelMap; + } else if (levels === configLevels) { + levelMap = logLevelMap; + } else if (levels === winston.config.npm.levels) { + levelMap = npmLogLevelMap; + } else { + return undefined; + } + for (const level of Object.keys(levelMap)) { + if (typeof level === 'string') { + continue; + } + if (logLevelMap[level] === levelName) { + return level; + } + } + return undefined; +} +export function getLevel(name: LogLevelName): LogLevel | undefined { + return resolveLevel(name); +} diff --git a/src/client/logging/logger.ts b/src/client/logging/logger.ts index 55246130a738..f6d29e83b9b9 100644 --- a/src/client/logging/logger.ts +++ b/src/client/logging/logger.ts @@ -2,94 +2,95 @@ // Licensed under the MIT License. 'use strict'; -// tslint:disable:no-any - import * as util from 'util'; -import { createLogger } from 'winston'; -import { isTestExecution } from '../common/constants'; -import { logToConsole, monkeypatchConsole } from './_console'; +import * as winston from 'winston'; +import * as Transport from 'winston-transport'; import { getFormatter } from './formatters'; -import { getConsoleTransport, getFileTransport } from './transports'; -import { LogLevel } from './types'; - -// Initialize the loggers as soon as this module is imported. -const consoleLogger = createLogger(); -const fileLogger = createLogger(); -initializeConsoleLogger(); -initializeFileLogger(); +import { LogLevel, resolveLevelName } from './levels'; +import { getConsoleTransport, getFileTransport, isConsoleTransport } from './transports'; +import { Arguments } from './util'; -// Convert from LogLevel enum to node console "stream" (logger method). -const logLevelMap = { - [LogLevel.Error]: 'error', - [LogLevel.Information]: 'info', - [LogLevel.Warning]: 'warn' +export type LoggerConfig = { + level?: LogLevel; + file?: { + logfile: string; + }; + console?: { + label?: string; + }; }; -// Emit a log message derived from the args to all enabled transports. -export function _log(logLevel: LogLevel, ...args: any[]) { - if (consoleLogger.transports.length > 0) { - const message = args.length === 0 ? '' : util.format(args[0], ...args.slice(1)); - consoleLogger.log(logLevelMap[logLevel], message); +// Create a logger just the way we like it. +export function createLogger(config?: LoggerConfig) { + const logger = winston.createLogger({ + // We would also set "levels" here. + }); + if (config) { + configureLogger(logger, config); } - logToFile(logLevel, ...args); + return logger; } -// Emit a log message derived from the args to a file, if enabled. -function logToFile(logLevel: LogLevel, ...args: any[]) { - if (fileLogger.transports.length === 0) { - return; - } - const message = args.length === 0 ? '' : util.format(args[0], ...args.slice(1)); - fileLogger.log(logLevelMap[logLevel], message); +interface IConfigurableLogger { + level: string; + add(transport: Transport): void; } -/** - * Initialize the logger for console. - * We do two things here: - * - Anything written to the logger will be displayed in the console window as well - * This is the behavior of the extension when running it. - * When running tests on CI, we might not want this behavior, as it'll pollute the - * test output with logging (as mentioned this is optional). - * Messages logged using our logger will be prefixed with `Python Extension: ....` for console window. - * This way, its easy to identify messages specific to the python extension. - * - Monkey patch the console.log and similar methods to send messages to the file logger. - * When running UI tests or similar, and we want to see everything that was dumped into `console window`, - * then we need to hijack the console logger. - * To do this we need to monkey patch the console methods. - * This is optional (generally done when running tests on CI). - */ -function initializeConsoleLogger() { - // Hijack `console.log` when running tests on CI. - if (process.env.VSC_PYTHON_LOG_FILE && process.env.TF_BUILD) { - monkeypatchConsole(logToFile); +// Set up a logger just the way we like it. +export function configureLogger(logger: IConfigurableLogger, config: LoggerConfig) { + if (config.level) { + const levelName = resolveLevelName(config.level); + if (levelName) { + logger.level = levelName; + } } - if (isTestExecution() && !process.env.VSC_PYTHON_FORCE_LOGGING) { - // Do not log to console if running tests on CI and we're not asked to do so. - return; + if (config.file) { + const formatter = getFormatter(); + const transport = getFileTransport(config.file.logfile, formatter); + logger.add(transport); + } + if (config.console) { + const formatter = getFormatter({ label: config.console.label }); + const transport = getConsoleTransport(formatter); + logger.add(transport); } +} - // Rest of this stuff is just to instantiate the console logger. - // I.e. when we use our logger, ensure we also log to the console (for end users). - const formatter = getFormatter({ - // In CI there's no need for the label. - label: process.env.TF_BUILD ? undefined : 'Python Extension:' - }); - const transport = getConsoleTransport(logToConsole, formatter); - consoleLogger.add(transport as any); +export interface ILogger { + transports: unknown[]; + levels: winston.config.AbstractConfigSetLevels; + log(level: string, message: string): void; +} + +// Emit a log message derived from the args to all enabled transports. +export function logToAll(loggers: ILogger[], logLevel: LogLevel, args: Arguments) { + const message = args.length === 0 ? '' : util.format(args[0], ...args.slice(1)); + for (const logger of loggers) { + if (logger.transports.length > 0) { + const levelName = getLevelName(logLevel, logger.levels, isConsoleLogger(logger)); + logger.log(levelName, message); + } + } +} + +function isConsoleLogger(logger: ILogger): boolean { + for (const transport of logger.transports) { + if (isConsoleTransport(transport)) { + return true; + } + } + return false; } -/** - * Send all logging output to a log file. - * We log to the file only if a file has been specified as an env variable. - * Currently this is setup on CI servers. - */ -function initializeFileLogger() { - const logfile = process.env.VSC_PYTHON_LOG_FILE; - if (!logfile) { - return; +function getLevelName(level: LogLevel, levels: winston.config.AbstractConfigSetLevels, isConsole?: boolean): string { + const levelName = resolveLevelName(level, levels); + if (levelName) { + return levelName; + } else if (isConsole) { + // XXX Hard-coding this is fragile: + return 'silly'; + } else { + return resolveLevelName(LogLevel.Info, levels) || 'info'; } - const formatter = getFormatter(); - const transport = getFileTransport(logfile, formatter); - fileLogger.add(transport); } diff --git a/src/client/logging/trace.ts b/src/client/logging/trace.ts new file mode 100644 index 000000000000..3191df5bd9d7 --- /dev/null +++ b/src/client/logging/trace.ts @@ -0,0 +1,77 @@ +// Copyright (c) Microsoft Corporation. All rights reserved. +// Licensed under the MIT License. +'use strict'; + +import { CallInfo, trace as traceDecorator } from '../common/utils/decorators'; +import { TraceInfo, tracing as _tracing } from '../common/utils/misc'; +import { sendTelemetryEvent } from '../telemetry'; +import { LogLevel } from './levels'; +import { ILogger, logToAll } from './logger'; +import { argsToLogString, returnValueToLogString } from './util'; + +// The information we want to log. +export enum TraceOptions { + None = 0, + Arguments = 1, + ReturnValue = 2 +} + +export function createTracingDecorator(loggers: ILogger[], logInfo: LogInfo) { + return traceDecorator((call, traced) => logResult(loggers, logInfo, traced, call)); +} + +// This is like a "context manager" that logs tracing info. +export function tracing(loggers: ILogger[], logInfo: LogInfo, run: () => T, call?: CallInfo): T { + return _tracing((traced) => logResult(loggers, logInfo, traced, call), run); +} + +export type LogInfo = { + opts: TraceOptions; + message: string; + level?: LogLevel; +}; + +function normalizeCall(call: CallInfo): CallInfo { + let { kind, name, args } = call; + if (!kind || kind === '') { + kind = 'Function'; + } + if (!name || name === '') { + name = ''; + } + if (!args) { + args = []; + } + return { kind, name, args }; +} + +function formatMessages(info: LogInfo, traced: TraceInfo, call?: CallInfo): string { + call = normalizeCall(call!); + const messages = [info.message]; + messages.push( + `${call.kind} name = ${call.name}`.trim(), + `completed in ${traced.elapsed}ms`, + `has a ${traced.returnValue ? 'truthy' : 'falsy'} return value` + ); + if ((info.opts & TraceOptions.Arguments) === TraceOptions.Arguments) { + messages.push(argsToLogString(call.args)); + } + if ((info.opts & TraceOptions.ReturnValue) === TraceOptions.ReturnValue) { + messages.push(returnValueToLogString(traced.returnValue)); + } + return messages.join(', '); +} + +function logResult(loggers: ILogger[], info: LogInfo, traced: TraceInfo, call?: CallInfo) { + const formatted = formatMessages(info, traced, call); + if (traced.err === undefined) { + // The call did not fail. + if (!info.level || info.level > LogLevel.Error) { + logToAll(loggers, LogLevel.Info, [formatted]); + } + } else { + logToAll(loggers, LogLevel.Error, [formatted, traced.err]); + // tslint:disable-next-line:no-any + sendTelemetryEvent('ERROR' as any, undefined, undefined, traced.err); + } +} diff --git a/src/client/logging/transports.ts b/src/client/logging/transports.ts index 03b779b5ce33..1fb45e158d0a 100644 --- a/src/client/logging/transports.ts +++ b/src/client/logging/transports.ts @@ -2,35 +2,69 @@ // Licensed under the MIT License. 'use strict'; -// tslint:disable:no-any - import * as logform from 'logform'; import * as path from 'path'; -import { transports } from 'winston'; +import * as winston from 'winston'; +import * as Transport from 'winston-transport'; import { EXTENSION_ROOT_DIR } from '../constants'; -import { ConsoleStreams } from './types'; +import { LogLevel, resolveLevel } from './levels'; +import { Arguments } from './util'; -// tslint:disable-next-line: no-var-requires no-require-imports -const TransportStream = require('winston-transport'); +const formattedMessage = Symbol.for('message'); -// Create a console-targeting transport that can be added to a winston logger. -export function getConsoleTransport( - logToConsole: (stream: ConsoleStreams, ...args: any[]) => void, - formatter: logform.Format -) { - const formattedMessage = Symbol.for('message'); - class ConsoleTransport extends TransportStream { - constructor(options?: any) { - super(options); +export function isConsoleTransport(transport: unknown): boolean { + // tslint:disable-next-line:no-any + return (transport as any).isConsole; +} + +// A winston-compatible transport type. +// We do not use transports.ConsoleTransport because it cannot +// adapt to our custom log levels very well. +class ConsoleTransport extends Transport { + // tslint:disable:no-console + private static funcByLevel: { [K in LogLevel]: (...args: Arguments) => void } = { + [LogLevel.Error]: console.error, + [LogLevel.Warn]: console.warn, + [LogLevel.Info]: console.info, + [LogLevel.Debug]: console.debug, + [LogLevel.Trace]: console.trace + }; + private static defaultFunc = console.log; + // tslint:enable:no-console + + // This is used to identify the type. + public readonly isConsole = true; + + constructor( + // tslint:disable-next-line:no-any + options?: any, + private readonly levels?: winston.config.AbstractConfigSetLevels + ) { + super(options); + } + + // tslint:disable-next-line:no-any + public log?(info: { level: string; message: string; [formattedMessage]: string }, next: () => void): any { + setImmediate(() => this.emit('logged', info)); + const level = resolveLevel(info.level, this.levels); + const msg = info[formattedMessage] || info.message; + this.logToConsole(level, msg); + if (next) { + next(); } - public log?(info: { level: string; message: string; [formattedMessage]: string }, next: () => void): any { - setImmediate(() => this.emit('logged', info)); - logToConsole(info.level as any, info[formattedMessage] || info.message); - if (next) { - next(); - } + } + + private logToConsole(level?: LogLevel, msg?: string) { + let func = ConsoleTransport.defaultFunc; + if (level) { + func = ConsoleTransport.funcByLevel[level] || func; } + func(msg); } +} + +// Create a console-targeting transport that can be added to a winston logger. +export function getConsoleTransport(formatter: logform.Format): Transport { return new ConsoleTransport({ // We minimize customization. format: formatter @@ -38,11 +72,11 @@ export function getConsoleTransport( } // Create a file-targeting transport that can be added to a winston logger. -export function getFileTransport(logfile: string, formatter: logform.Format) { +export function getFileTransport(logfile: string, formatter: logform.Format): Transport { if (!path.isAbsolute(logfile)) { logfile = path.join(EXTENSION_ROOT_DIR, logfile); } - return new transports.File({ + return new winston.transports.File({ format: formatter, filename: logfile, handleExceptions: true diff --git a/src/client/logging/types.ts b/src/client/logging/types.ts deleted file mode 100644 index d769bff5e189..000000000000 --- a/src/client/logging/types.ts +++ /dev/null @@ -1,25 +0,0 @@ -// Copyright (c) Microsoft Corporation. All rights reserved. -// Licensed under the MIT License. -'use strict'; - -// The various supported log levels. The number value matches (npm) winston. -export enum LogLevel { - Error = 0, - Warning = 1, - Information = 2 -} - -// The logging "streams" (methods) of the node console. -export type ConsoleStreams = 'log' | 'error' | 'warn' | 'info' | 'debug'; - -// Knobs used when creating a formatter. -export type FormatterOptions = { - label?: string; -}; - -// The information we want to log. -export enum TraceOptions { - None = 0, - Arguments = 1, - ReturnValue = 2 -} diff --git a/src/client/logging/util.ts b/src/client/logging/util.ts index 2cab65bed14d..79d977136a89 100644 --- a/src/client/logging/util.ts +++ b/src/client/logging/util.ts @@ -3,30 +3,39 @@ 'use strict'; // tslint:disable-next-line:no-any -type Arguments = any[]; +export type Arguments = any[]; + +function valueToLogString(value: unknown, kind: string): string { + if (value === undefined) { + return 'undefined'; + } + if (value === null) { + return 'null'; + } + try { + // tslint:disable-next-line:no-any + if (value && (value as any).fsPath) { + // tslint:disable-next-line:no-any + return ``; + } + return JSON.stringify(value); + } catch { + return `<${kind} cannot be serialized for logging>`; + } +} // Convert the given array of values (func call arguments) into a string // suitable to be used in a log message. export function argsToLogString(args: Arguments): string { + if (!args) { + return ''; + } try { - return (args || []) - .map((item, index) => { - if (item === undefined) { - return `Arg ${index + 1}: undefined`; - } - if (item === null) { - return `Arg ${index + 1}: null`; - } - try { - if (item && item.fsPath) { - return `Arg ${index + 1}: `; - } - return `Arg ${index + 1}: ${JSON.stringify(item)}`; - } catch { - return `Arg ${index + 1}: `; - } - }) - .join(', '); + const argStrings = args.map((item, index) => { + const valueString = valueToLogString(item, 'argument'); + return `Arg ${index + 1}: ${valueString}`; + }); + return argStrings.join(', '); } catch { return ''; } @@ -35,16 +44,6 @@ export function argsToLogString(args: Arguments): string { // Convert the given return value into a string // suitable to be used in a log message. export function returnValueToLogString(returnValue: unknown): string { - const returnValueMessage = 'Return Value: '; - if (returnValue === undefined) { - return `${returnValueMessage}undefined`; - } - if (returnValue === null) { - return `${returnValueMessage}null`; - } - try { - return `${returnValueMessage}${JSON.stringify(returnValue)}`; - } catch { - return `${returnValueMessage}`; - } + const valueString = valueToLogString(returnValue, 'Return value'); + return `Return Value: ${valueString}`; }