diff --git a/src/client/common/logger.ts b/src/client/common/logger.ts index d332dd6028e5..f43a633ffd45 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, - logError as traceError, - logInfo as traceInfo, - logVerbose as traceVerbose, - logWarning as traceWarning -} from '../logging'; -export { TraceOptions as LogOptions } from '../logging/trace'; + traceError, + traceInfo, + traceVerbose, + traceWarning +} from '../logging/_trace'; +export { TraceOptions as LogOptions } from '../logging/types'; diff --git a/src/client/common/utils/async.ts b/src/client/common/utils/async.ts index 030ac00b7c10..8ecd281a862d 100644 --- a/src/client/common/utils/async.ts +++ b/src/client/common/utils/async.ts @@ -27,16 +27,6 @@ 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 512f31e65e19..e0e85bfded1b 100644 --- a/src/client/common/utils/decorators.ts +++ b/src/client/common/utils/decorators.ts @@ -8,7 +8,6 @@ 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'); @@ -226,37 +225,3 @@ 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 972e197d3eba..1f21921fe6f6 100644 --- a/src/client/common/utils/misc.ts +++ b/src/client/common/utils/misc.ts @@ -4,8 +4,6 @@ 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() {} @@ -40,46 +38,6 @@ 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 new file mode 100644 index 000000000000..a628c94e852b --- /dev/null +++ b/src/client/logging/_console.ts @@ -0,0 +1,74 @@ +// 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 deleted file mode 100644 index 6577725ef56d..000000000000 --- a/src/client/logging/_global.ts +++ /dev/null @@ -1,157 +0,0 @@ -// 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 new file mode 100644 index 000000000000..fca65c199735 --- /dev/null +++ b/src/client/logging/_trace.ts @@ -0,0 +1,110 @@ +// 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 b3dd4e52761f..1867186d09c2 100644 --- a/src/client/logging/formatters.ts +++ b/src/client/logging/formatters.ts @@ -3,47 +3,28 @@ 'use strict'; import { format } from 'winston'; -import { getLevel, LogLevel, LogLevelName } from './levels'; +import { FormatterOptions } from './types'; const TIMESTAMP = 'YYYY-MM-DD HH:mm:ss'; -// Knobs used when creating a formatter. -export type FormatterOptions = { - label?: string; -}; - +// Return a consistent representation of the given log level. +// // Pascal casing is used so log files get highlighted when viewing // in VSC and other editors. -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()}`; +function normalizeLevel(level: string): string { + return `${level.substring(0, 1).toUpperCase()}${level.substring(1)}`; } // Return a log entry that can be emitted as-is. -function formatMessage(level: LogLevelName, timestamp: string, message: string): string { - const levelFormatted = normalizeLevel(level); - return `${levelFormatted} ${timestamp}: ${message}`; +function formatMessage(level: string, timestamp: string, message: string): string { + level = normalizeLevel(level); + return `${level} ${timestamp}: ${message}`; } // Return a log entry that can be emitted as-is. -function formatLabeledMessage(level: LogLevelName, timestamp: string, label: string, message: string): string { - const levelFormatted = normalizeLevel(level); - return `${levelFormatted} ${label} ${timestamp}: ${message}`; +function formatLabeledMessage(level: string, timestamp: string, label: string, message: string): string { + level = normalizeLevel(level); + return `${level} ${label} ${timestamp}: ${message}`; } // Return a minimal format object that can be used with a "winston" @@ -52,8 +33,8 @@ function getMinimalFormatter() { return format.combine( format.timestamp({ format: TIMESTAMP }), format.printf( - // This relies on the timestamp formatter we added above: - ({ level, message, timestamp }) => formatMessage(level as LogLevelName, timestamp, message) + // a minimal message + ({ level, message, timestamp }) => formatMessage(level, timestamp, message) ) ); } @@ -65,9 +46,8 @@ function getLabeledFormatter(label_: string) { format.label({ label: label_ }), format.timestamp({ format: TIMESTAMP }), format.printf( - // This relies on the label and timestamp formatters we added above: - ({ level, message, label, timestamp }) => - formatLabeledMessage(level as LogLevelName, timestamp, label, message) + // mostly a minimal message + ({ level, message, label, timestamp }) => formatLabeledMessage(level, timestamp, label, message) ) ); } diff --git a/src/client/logging/index.ts b/src/client/logging/index.ts index 19dc23d0bfa6..6da41c569a13 100644 --- a/src/client/logging/index.ts +++ b/src/client/logging/index.ts @@ -5,10 +5,9 @@ export { // aliases // (for convenience) - logError, - logInfo, - logVerbose, - logWarning, traceDecorators, - tracing -} from './_global'; + traceError, + traceInfo, + traceVerbose, + traceWarning +} from './_trace'; diff --git a/src/client/logging/levels.ts b/src/client/logging/levels.ts deleted file mode 100644 index d857946a6c75..000000000000 --- a/src/client/logging/levels.ts +++ /dev/null @@ -1,100 +0,0 @@ -// 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 f6d29e83b9b9..55246130a738 100644 --- a/src/client/logging/logger.ts +++ b/src/client/logging/logger.ts @@ -2,95 +2,94 @@ // Licensed under the MIT License. 'use strict'; +// tslint:disable:no-any + import * as util from 'util'; -import * as winston from 'winston'; -import * as Transport from 'winston-transport'; +import { createLogger } from 'winston'; +import { isTestExecution } from '../common/constants'; +import { logToConsole, monkeypatchConsole } from './_console'; import { getFormatter } from './formatters'; -import { LogLevel, resolveLevelName } from './levels'; -import { getConsoleTransport, getFileTransport, isConsoleTransport } from './transports'; -import { Arguments } from './util'; +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(); -export type LoggerConfig = { - level?: LogLevel; - file?: { - logfile: string; - }; - console?: { - label?: string; - }; +// Convert from LogLevel enum to node console "stream" (logger method). +const logLevelMap = { + [LogLevel.Error]: 'error', + [LogLevel.Information]: 'info', + [LogLevel.Warning]: 'warn' }; -// 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); +// 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); } - return logger; + logToFile(logLevel, ...args); } -interface IConfigurableLogger { - level: string; - add(transport: Transport): void; -} - -// 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 (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); +// 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); } -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); - } +/** + * 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); } -} -function isConsoleLogger(logger: ILogger): boolean { - for (const transport of logger.transports) { - if (isConsoleTransport(transport)) { - return true; - } + 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; } - return false; + + // 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); } -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'; +/** + * 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; } + 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 deleted file mode 100644 index 3191df5bd9d7..000000000000 --- a/src/client/logging/trace.ts +++ /dev/null @@ -1,77 +0,0 @@ -// 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 1fb45e158d0a..03b779b5ce33 100644 --- a/src/client/logging/transports.ts +++ b/src/client/logging/transports.ts @@ -2,69 +2,35 @@ // Licensed under the MIT License. 'use strict'; +// tslint:disable:no-any + import * as logform from 'logform'; import * as path from 'path'; -import * as winston from 'winston'; -import * as Transport from 'winston-transport'; +import { transports } from 'winston'; import { EXTENSION_ROOT_DIR } from '../constants'; -import { LogLevel, resolveLevel } from './levels'; -import { Arguments } from './util'; - -const formattedMessage = Symbol.for('message'); - -export function isConsoleTransport(transport: unknown): boolean { - // tslint:disable-next-line:no-any - return (transport as any).isConsole; -} +import { ConsoleStreams } from './types'; -// 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-var-requires no-require-imports +const TransportStream = require('winston-transport'); - // 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(); +// 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); } - } - - private logToConsole(level?: LogLevel, msg?: string) { - let func = ConsoleTransport.defaultFunc; - if (level) { - func = ConsoleTransport.funcByLevel[level] || func; + 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(); + } } - 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 @@ -72,11 +38,11 @@ export function getConsoleTransport(formatter: logform.Format): Transport { } // Create a file-targeting transport that can be added to a winston logger. -export function getFileTransport(logfile: string, formatter: logform.Format): Transport { +export function getFileTransport(logfile: string, formatter: logform.Format) { if (!path.isAbsolute(logfile)) { logfile = path.join(EXTENSION_ROOT_DIR, logfile); } - return new winston.transports.File({ + return new transports.File({ format: formatter, filename: logfile, handleExceptions: true diff --git a/src/client/logging/types.ts b/src/client/logging/types.ts new file mode 100644 index 000000000000..d769bff5e189 --- /dev/null +++ b/src/client/logging/types.ts @@ -0,0 +1,25 @@ +// 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 79d977136a89..2cab65bed14d 100644 --- a/src/client/logging/util.ts +++ b/src/client/logging/util.ts @@ -3,39 +3,30 @@ 'use strict'; // tslint:disable-next-line:no-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>`; - } -} +type Arguments = any[]; // 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 { - const argStrings = args.map((item, index) => { - const valueString = valueToLogString(item, 'argument'); - return `Arg ${index + 1}: ${valueString}`; - }); - return argStrings.join(', '); + 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(', '); } catch { return ''; } @@ -44,6 +35,16 @@ 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 valueString = valueToLogString(returnValue, 'Return value'); - return `Return Value: ${valueString}`; + 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}`; + } }