From 2fbd1d4404f90a869b12354c0d26b8676d455155 Mon Sep 17 00:00:00 2001 From: Eric Snow Date: Tue, 14 Apr 2020 11:56:24 -0600 Subject: [PATCH 01/13] Move logger code to src/client/logging/. --- src/client/common/logger.ts | 348 +----------------------------------- src/client/logging/index.ts | 344 +++++++++++++++++++++++++++++++++++ 2 files changed, 353 insertions(+), 339 deletions(-) create mode 100644 src/client/logging/index.ts diff --git a/src/client/common/logger.ts b/src/client/common/logger.ts index 4f4979fe04a0..70772a2a8244 100644 --- a/src/client/common/logger.ts +++ b/src/client/common/logger.ts @@ -1,339 +1,9 @@ -// tslint:disable:no-console no-any -import * as path from 'path'; -import * as util from 'util'; -import { createLogger, format, transports } from 'winston'; -import { EXTENSION_ROOT_DIR } from '../constants'; -import { sendTelemetryEvent } from '../telemetry'; -import { isTestExecution } from './constants'; -import { LogLevel } from './types'; -import { StopWatch } from './utils/stopWatch'; - -// tslint:disable-next-line: no-var-requires no-require-imports -const TransportStream = require('winston-transport'); - -// Initialize the loggers as soon as this module is imported. -const consoleLogger = createLogger(); -const fileLogger = createLogger(); -initializeConsoleLogger(); -initializeFileLogger(); - -const logLevelMap = { - [LogLevel.Error]: 'error', - [LogLevel.Information]: 'info', - [LogLevel.Warning]: 'warn' -}; - -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); - } - logToFile(logLevel, ...args); -} -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); -} - -/** - * 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). - */ -// tslint:disable-next-line: max-func-body-length -function initializeConsoleLogger() { - const logMethods = { - log: Symbol.for('log'), - info: Symbol.for('info'), - error: Symbol.for('error'), - debug: Symbol.for('debug'), - warn: Symbol.for('warn') - }; - - function logToConsole(stream: 'info' | 'error' | 'warn' | 'log' | 'debug', ...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); - } - - // Hijack `console.log` when running tests on CI. - if (process.env.VSC_PYTHON_LOG_FILE && process.env.TF_BUILD) { - /* - 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). - */ - // 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); - }; - } - - 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; - } - - // 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 formattedMessage = Symbol.for('message'); - class ConsoleTransport extends TransportStream { - constructor(options?: any) { - super(options); - } - 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(); - } - } - } - const consoleFormatter = format.printf(({ level, message, label, timestamp }) => { - // If we're on CI server, no need for the label (prefix) - // Pascal casing og log level, so log files get highlighted when viewing in VSC and other editors. - const prefix = `${level.substring(0, 1).toUpperCase()}${level.substring(1)} ${ - process.env.TF_BUILD ? '' : label - }`; - return `${prefix.trim()} ${timestamp}: ${message}`; - }); - const consoleFormat = format.combine( - format.label({ label: 'Python Extension:' }), - format.timestamp({ - format: 'YYYY-MM-DD HH:mm:ss' - }), - consoleFormatter - ); - consoleLogger.add(new ConsoleTransport({ format: consoleFormat }) as any); -} - -/** - * 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() { - if (!process.env.VSC_PYTHON_LOG_FILE) { - return; - } - const fileFormatter = format.printf(({ level, message, timestamp }) => { - // Pascal casing og log level, so log files get highlighted when viewing in VSC and other editors. - return `${level.substring(0, 1).toUpperCase()}${level.substring(1)} ${timestamp}: ${message}`; - }); - const fileFormat = format.combine( - format.timestamp({ - format: 'YYYY-MM-DD HH:mm:ss' - }), - fileFormatter - ); - const logFilePath = path.isAbsolute(process.env.VSC_PYTHON_LOG_FILE) - ? process.env.VSC_PYTHON_LOG_FILE - : path.join(EXTENSION_ROOT_DIR, process.env.VSC_PYTHON_LOG_FILE); - const logFileSink = new transports.File({ - format: fileFormat, - filename: logFilePath, - handleExceptions: true - }); - fileLogger.add(logFileSink); -} - -/** - * What do we want to log. - * @export - * @enum {number} - */ -export enum LogOptions { - None = 0, - Arguments = 1, - ReturnValue = 2 -} - -// tslint:disable-next-line:no-any -function argsToLogString(args: any[]): string { - 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(', '); - } catch { - return ''; - } -} - -// tslint:disable-next-line:no-any -function returnValueToLogString(returnValue: any): 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}`; - } -} - -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, options: LogOptions = LogOptions.Arguments | LogOptions.ReturnValue) { - return trace(message, options); - } - export function error(message: string) { - return trace(message, LogOptions.Arguments | LogOptions.ReturnValue, LogLevel.Error); - } - export function info(message: string) { - return trace(message); - } - export function warn(message: string) { - return trace(message, LogOptions.Arguments | LogOptions.ReturnValue, LogLevel.Warning); - } -} -function trace(message: string, options: LogOptions = LogOptions.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 ((options & LogOptions.Arguments) === LogOptions.Arguments) { - messagesToLog.push(argsToLogString(args)); - } - if ((options & LogOptions.ReturnValue) === LogOptions.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; - }; -} +export { + // aliases: + LogOptions, + traceDecorators, + traceError, + traceInfo, + traceVerbose, + traceWarning +} from '../logging'; diff --git a/src/client/logging/index.ts b/src/client/logging/index.ts new file mode 100644 index 000000000000..0dd6569db7c4 --- /dev/null +++ b/src/client/logging/index.ts @@ -0,0 +1,344 @@ +// Copyright (c) Microsoft Corporation. All rights reserved. +// Licensed under the MIT License. +'use strict'; + +// tslint:disable:no-console no-any + +import * as path from 'path'; +import * as util from 'util'; +import { createLogger, format, transports } from 'winston'; +import { isTestExecution } from '../common/constants'; +import { LogLevel } from '../common/types'; +import { StopWatch } from '../common/utils/stopWatch'; +import { EXTENSION_ROOT_DIR } from '../constants'; +import { sendTelemetryEvent } from '../telemetry'; + +// tslint:disable-next-line: no-var-requires no-require-imports +const TransportStream = require('winston-transport'); + +// Initialize the loggers as soon as this module is imported. +const consoleLogger = createLogger(); +const fileLogger = createLogger(); +initializeConsoleLogger(); +initializeFileLogger(); + +const logLevelMap = { + [LogLevel.Error]: 'error', + [LogLevel.Information]: 'info', + [LogLevel.Warning]: 'warn' +}; + +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); + } + logToFile(logLevel, ...args); +} +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); +} + +/** + * 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). + */ +// tslint:disable-next-line: max-func-body-length +function initializeConsoleLogger() { + const logMethods = { + log: Symbol.for('log'), + info: Symbol.for('info'), + error: Symbol.for('error'), + debug: Symbol.for('debug'), + warn: Symbol.for('warn') + }; + + function logToConsole(stream: 'info' | 'error' | 'warn' | 'log' | 'debug', ...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); + } + + // Hijack `console.log` when running tests on CI. + if (process.env.VSC_PYTHON_LOG_FILE && process.env.TF_BUILD) { + /* + 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). + */ + // 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); + }; + } + + 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; + } + + // 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 formattedMessage = Symbol.for('message'); + class ConsoleTransport extends TransportStream { + constructor(options?: any) { + super(options); + } + 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(); + } + } + } + const consoleFormatter = format.printf(({ level, message, label, timestamp }) => { + // If we're on CI server, no need for the label (prefix) + // Pascal casing og log level, so log files get highlighted when viewing in VSC and other editors. + const prefix = `${level.substring(0, 1).toUpperCase()}${level.substring(1)} ${ + process.env.TF_BUILD ? '' : label + }`; + return `${prefix.trim()} ${timestamp}: ${message}`; + }); + const consoleFormat = format.combine( + format.label({ label: 'Python Extension:' }), + format.timestamp({ + format: 'YYYY-MM-DD HH:mm:ss' + }), + consoleFormatter + ); + consoleLogger.add(new ConsoleTransport({ format: consoleFormat }) as any); +} + +/** + * 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() { + if (!process.env.VSC_PYTHON_LOG_FILE) { + return; + } + const fileFormatter = format.printf(({ level, message, timestamp }) => { + // Pascal casing og log level, so log files get highlighted when viewing in VSC and other editors. + return `${level.substring(0, 1).toUpperCase()}${level.substring(1)} ${timestamp}: ${message}`; + }); + const fileFormat = format.combine( + format.timestamp({ + format: 'YYYY-MM-DD HH:mm:ss' + }), + fileFormatter + ); + const logFilePath = path.isAbsolute(process.env.VSC_PYTHON_LOG_FILE) + ? process.env.VSC_PYTHON_LOG_FILE + : path.join(EXTENSION_ROOT_DIR, process.env.VSC_PYTHON_LOG_FILE); + const logFileSink = new transports.File({ + format: fileFormat, + filename: logFilePath, + handleExceptions: true + }); + fileLogger.add(logFileSink); +} + +/** + * What do we want to log. + * @export + * @enum {number} + */ +export enum LogOptions { + None = 0, + Arguments = 1, + ReturnValue = 2 +} + +// tslint:disable-next-line:no-any +function argsToLogString(args: any[]): string { + 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(', '); + } catch { + return ''; + } +} + +// tslint:disable-next-line:no-any +function returnValueToLogString(returnValue: any): 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}`; + } +} + +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, options: LogOptions = LogOptions.Arguments | LogOptions.ReturnValue) { + return trace(message, options); + } + export function error(message: string) { + return trace(message, LogOptions.Arguments | LogOptions.ReturnValue, LogLevel.Error); + } + export function info(message: string) { + return trace(message); + } + export function warn(message: string) { + return trace(message, LogOptions.Arguments | LogOptions.ReturnValue, LogLevel.Warning); + } +} +function trace(message: string, options: LogOptions = LogOptions.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 ((options & LogOptions.Arguments) === LogOptions.Arguments) { + messagesToLog.push(argsToLogString(args)); + } + if ((options & LogOptions.ReturnValue) === LogOptions.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; + }; +} From 934dd22bd755c1730ccec19c3cc7257a9f839ec0 Mon Sep 17 00:00:00 2001 From: Eric Snow Date: Tue, 14 Apr 2020 12:08:21 -0600 Subject: [PATCH 02/13] Factor out logging types. --- src/client/common/logger.ts | 2 +- src/client/common/types.ts | 14 +++++++------- src/client/logging/index.ts | 27 ++++++++------------------- src/client/logging/types.ts | 17 +++++++++++++++++ 4 files changed, 33 insertions(+), 27 deletions(-) create mode 100644 src/client/logging/types.ts diff --git a/src/client/common/logger.ts b/src/client/common/logger.ts index 70772a2a8244..fdce6b295fb8 100644 --- a/src/client/common/logger.ts +++ b/src/client/common/logger.ts @@ -1,9 +1,9 @@ export { // aliases: - LogOptions, traceDecorators, traceError, traceInfo, traceVerbose, traceWarning } from '../logging'; +export { TraceOptions as LogOptions } from '../logging/types'; diff --git a/src/client/common/types.ts b/src/client/common/types.ts index 656af6d5ff22..bd9d6da77f13 100644 --- a/src/client/common/types.ts +++ b/src/client/common/types.ts @@ -65,12 +65,6 @@ export type ExecutionInfo = { product?: Product; }; -export enum LogLevel { - Information = 'Information', - Error = 'Error', - Warning = 'Warning' -} - export enum InstallerResponse { Installed, Disabled, @@ -313,6 +307,12 @@ export interface IExperiments { readonly optOutFrom: string[]; } +export enum AnalysisSettingsLogLevel { + Information = 'Information', + Error = 'Error', + Warning = 'Warning' +} + export type LanguageServerDownloadChannels = 'stable' | 'beta' | 'daily'; export interface IAnalysisSettings { readonly downloadChannel?: LanguageServerDownloadChannels; @@ -324,7 +324,7 @@ export interface IAnalysisSettings { readonly information: string[]; readonly disabled: string[]; readonly traceLogging: boolean; - readonly logLevel: LogLevel; + readonly logLevel: AnalysisSettingsLogLevel; } export interface IVariableQuery { diff --git a/src/client/logging/index.ts b/src/client/logging/index.ts index 0dd6569db7c4..3e5454490a0c 100644 --- a/src/client/logging/index.ts +++ b/src/client/logging/index.ts @@ -8,10 +8,10 @@ import * as path from 'path'; import * as util from 'util'; import { createLogger, format, transports } from 'winston'; import { isTestExecution } from '../common/constants'; -import { LogLevel } from '../common/types'; import { StopWatch } from '../common/utils/stopWatch'; import { EXTENSION_ROOT_DIR } from '../constants'; import { sendTelemetryEvent } from '../telemetry'; +import { LogLevel, TraceOptions } from './types'; // tslint:disable-next-line: no-var-requires no-require-imports const TransportStream = require('winston-transport'); @@ -192,17 +192,6 @@ function initializeFileLogger() { fileLogger.add(logFileSink); } -/** - * What do we want to log. - * @export - * @enum {number} - */ -export enum LogOptions { - None = 0, - Arguments = 1, - ReturnValue = 2 -} - // tslint:disable-next-line:no-any function argsToLogString(args: any[]): string { try { @@ -262,20 +251,20 @@ export function traceWarning(...args: any[]) { } export namespace traceDecorators { - export function verbose(message: string, options: LogOptions = LogOptions.Arguments | LogOptions.ReturnValue) { - return trace(message, options); + export function verbose(message: string, opts: TraceOptions = TraceOptions.Arguments | TraceOptions.ReturnValue) { + return trace(message, opts); } export function error(message: string) { - return trace(message, LogOptions.Arguments | LogOptions.ReturnValue, LogLevel.Error); + 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, LogOptions.Arguments | LogOptions.ReturnValue, LogLevel.Warning); + return trace(message, TraceOptions.Arguments | TraceOptions.ReturnValue, LogLevel.Warning); } } -function trace(message: string, options: LogOptions = LogOptions.None, logLevel?: LogLevel) { +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; @@ -300,10 +289,10 @@ function trace(message: string, options: LogOptions = LogOptions.None, logLevel? returnValue ? 'truthy' : 'falsy' } return value` ); - if ((options & LogOptions.Arguments) === LogOptions.Arguments) { + if ((opts & TraceOptions.Arguments) === TraceOptions.Arguments) { messagesToLog.push(argsToLogString(args)); } - if ((options & LogOptions.ReturnValue) === LogOptions.ReturnValue) { + if ((opts & TraceOptions.ReturnValue) === TraceOptions.ReturnValue) { messagesToLog.push(returnValueToLogString(returnValue)); } if (ex) { diff --git a/src/client/logging/types.ts b/src/client/logging/types.ts new file mode 100644 index 000000000000..b477945a6bfd --- /dev/null +++ b/src/client/logging/types.ts @@ -0,0 +1,17 @@ +// 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 information we want to log. +export enum TraceOptions { + None = 0, + Arguments = 1, + ReturnValue = 2 +} From dbc0c1c64ad4faa5893dc6d8b32c507fb7db3d82 Mon Sep 17 00:00:00 2001 From: Eric Snow Date: Tue, 14 Apr 2020 12:25:04 -0600 Subject: [PATCH 03/13] Move logging utils to a dedicated module. --- src/client/logging/index.ts | 43 +------------------------------ src/client/logging/util.ts | 50 +++++++++++++++++++++++++++++++++++++ 2 files changed, 51 insertions(+), 42 deletions(-) create mode 100644 src/client/logging/util.ts diff --git a/src/client/logging/index.ts b/src/client/logging/index.ts index 3e5454490a0c..86654d7b4f4f 100644 --- a/src/client/logging/index.ts +++ b/src/client/logging/index.ts @@ -12,6 +12,7 @@ import { StopWatch } from '../common/utils/stopWatch'; import { EXTENSION_ROOT_DIR } from '../constants'; import { sendTelemetryEvent } from '../telemetry'; import { LogLevel, TraceOptions } from './types'; +import { argsToLogString, returnValueToLogString } from './util'; // tslint:disable-next-line: no-var-requires no-require-imports const TransportStream = require('winston-transport'); @@ -192,48 +193,6 @@ function initializeFileLogger() { fileLogger.add(logFileSink); } -// tslint:disable-next-line:no-any -function argsToLogString(args: any[]): string { - 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(', '); - } catch { - return ''; - } -} - -// tslint:disable-next-line:no-any -function returnValueToLogString(returnValue: any): 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}`; - } -} - export function traceVerbose(...args: any[]) { log(LogLevel.Information, ...args); } diff --git a/src/client/logging/util.ts b/src/client/logging/util.ts new file mode 100644 index 000000000000..2cab65bed14d --- /dev/null +++ b/src/client/logging/util.ts @@ -0,0 +1,50 @@ +// Copyright (c) Microsoft Corporation. All rights reserved. +// Licensed under the MIT License. +'use strict'; + +// tslint:disable-next-line:no-any +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 { + 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(', '); + } catch { + return ''; + } +} + +// 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}`; + } +} From 925201ddea383117ff837e375577f10ed9c71921 Mon Sep 17 00:00:00 2001 From: Eric Snow Date: Tue, 14 Apr 2020 12:43:02 -0600 Subject: [PATCH 04/13] Move the general logger code to a dedicated module. --- src/client/logging/index.ts | 187 +-------------------------------- src/client/logging/logger.ts | 195 +++++++++++++++++++++++++++++++++++ 2 files changed, 197 insertions(+), 185 deletions(-) create mode 100644 src/client/logging/logger.ts diff --git a/src/client/logging/index.ts b/src/client/logging/index.ts index 86654d7b4f4f..41a8c545ff82 100644 --- a/src/client/logging/index.ts +++ b/src/client/logging/index.ts @@ -2,197 +2,14 @@ // Licensed under the MIT License. 'use strict'; -// tslint:disable:no-console no-any +// tslint:disable:no-any -import * as path from 'path'; -import * as util from 'util'; -import { createLogger, format, transports } from 'winston'; -import { isTestExecution } from '../common/constants'; import { StopWatch } from '../common/utils/stopWatch'; -import { EXTENSION_ROOT_DIR } from '../constants'; import { sendTelemetryEvent } from '../telemetry'; +import { _log as log } from './logger'; import { LogLevel, TraceOptions } from './types'; import { argsToLogString, returnValueToLogString } from './util'; -// tslint:disable-next-line: no-var-requires no-require-imports -const TransportStream = require('winston-transport'); - -// Initialize the loggers as soon as this module is imported. -const consoleLogger = createLogger(); -const fileLogger = createLogger(); -initializeConsoleLogger(); -initializeFileLogger(); - -const logLevelMap = { - [LogLevel.Error]: 'error', - [LogLevel.Information]: 'info', - [LogLevel.Warning]: 'warn' -}; - -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); - } - logToFile(logLevel, ...args); -} -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); -} - -/** - * 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). - */ -// tslint:disable-next-line: max-func-body-length -function initializeConsoleLogger() { - const logMethods = { - log: Symbol.for('log'), - info: Symbol.for('info'), - error: Symbol.for('error'), - debug: Symbol.for('debug'), - warn: Symbol.for('warn') - }; - - function logToConsole(stream: 'info' | 'error' | 'warn' | 'log' | 'debug', ...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); - } - - // Hijack `console.log` when running tests on CI. - if (process.env.VSC_PYTHON_LOG_FILE && process.env.TF_BUILD) { - /* - 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). - */ - // 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); - }; - } - - 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; - } - - // 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 formattedMessage = Symbol.for('message'); - class ConsoleTransport extends TransportStream { - constructor(options?: any) { - super(options); - } - 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(); - } - } - } - const consoleFormatter = format.printf(({ level, message, label, timestamp }) => { - // If we're on CI server, no need for the label (prefix) - // Pascal casing og log level, so log files get highlighted when viewing in VSC and other editors. - const prefix = `${level.substring(0, 1).toUpperCase()}${level.substring(1)} ${ - process.env.TF_BUILD ? '' : label - }`; - return `${prefix.trim()} ${timestamp}: ${message}`; - }); - const consoleFormat = format.combine( - format.label({ label: 'Python Extension:' }), - format.timestamp({ - format: 'YYYY-MM-DD HH:mm:ss' - }), - consoleFormatter - ); - consoleLogger.add(new ConsoleTransport({ format: consoleFormat }) as any); -} - -/** - * 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() { - if (!process.env.VSC_PYTHON_LOG_FILE) { - return; - } - const fileFormatter = format.printf(({ level, message, timestamp }) => { - // Pascal casing og log level, so log files get highlighted when viewing in VSC and other editors. - return `${level.substring(0, 1).toUpperCase()}${level.substring(1)} ${timestamp}: ${message}`; - }); - const fileFormat = format.combine( - format.timestamp({ - format: 'YYYY-MM-DD HH:mm:ss' - }), - fileFormatter - ); - const logFilePath = path.isAbsolute(process.env.VSC_PYTHON_LOG_FILE) - ? process.env.VSC_PYTHON_LOG_FILE - : path.join(EXTENSION_ROOT_DIR, process.env.VSC_PYTHON_LOG_FILE); - const logFileSink = new transports.File({ - format: fileFormat, - filename: logFilePath, - handleExceptions: true - }); - fileLogger.add(logFileSink); -} - export function traceVerbose(...args: any[]) { log(LogLevel.Information, ...args); } diff --git a/src/client/logging/logger.ts b/src/client/logging/logger.ts new file mode 100644 index 000000000000..0fde9f5e3315 --- /dev/null +++ b/src/client/logging/logger.ts @@ -0,0 +1,195 @@ +// Copyright (c) Microsoft Corporation. All rights reserved. +// Licensed under the MIT License. +'use strict'; + +// tslint:disable:no-console no-any + +import * as path from 'path'; +import * as util from 'util'; +import { createLogger, format, transports } from 'winston'; +import { isTestExecution } from '../common/constants'; +import { EXTENSION_ROOT_DIR } from '../constants'; +import { LogLevel } from './types'; + +// tslint:disable-next-line: no-var-requires no-require-imports +const TransportStream = require('winston-transport'); + +// Initialize the loggers as soon as this module is imported. +const consoleLogger = createLogger(); +const fileLogger = createLogger(); +initializeConsoleLogger(); +initializeFileLogger(); + +// Convert from LogLevel enum to node console "stream" (logger method). +const logLevelMap = { + [LogLevel.Error]: 'error', + [LogLevel.Information]: 'info', + [LogLevel.Warning]: 'warn' +}; + +// 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); + } + logToFile(logLevel, ...args); +} + +// 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); +} + +/** + * 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). + */ +// tslint:disable-next-line: max-func-body-length +function initializeConsoleLogger() { + const logMethods = { + log: Symbol.for('log'), + info: Symbol.for('info'), + error: Symbol.for('error'), + debug: Symbol.for('debug'), + warn: Symbol.for('warn') + }; + + function logToConsole(stream: 'info' | 'error' | 'warn' | 'log' | 'debug', ...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); + } + + // Hijack `console.log` when running tests on CI. + if (process.env.VSC_PYTHON_LOG_FILE && process.env.TF_BUILD) { + /* + 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). + */ + // 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); + }; + } + + 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; + } + + // 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 formattedMessage = Symbol.for('message'); + class ConsoleTransport extends TransportStream { + constructor(options?: any) { + super(options); + } + 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(); + } + } + } + const consoleFormatter = format.printf(({ level, message, label, timestamp }) => { + // If we're on CI server, no need for the label (prefix) + // Pascal casing og log level, so log files get highlighted when viewing in VSC and other editors. + const prefix = `${level.substring(0, 1).toUpperCase()}${level.substring(1)} ${ + process.env.TF_BUILD ? '' : label + }`; + return `${prefix.trim()} ${timestamp}: ${message}`; + }); + const consoleFormat = format.combine( + format.label({ label: 'Python Extension:' }), + format.timestamp({ + format: 'YYYY-MM-DD HH:mm:ss' + }), + consoleFormatter + ); + consoleLogger.add(new ConsoleTransport({ format: consoleFormat }) as any); +} + +/** + * 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() { + if (!process.env.VSC_PYTHON_LOG_FILE) { + return; + } + const fileFormatter = format.printf(({ level, message, timestamp }) => { + // Pascal casing og log level, so log files get highlighted when viewing in VSC and other editors. + return `${level.substring(0, 1).toUpperCase()}${level.substring(1)} ${timestamp}: ${message}`; + }); + const fileFormat = format.combine( + format.timestamp({ + format: 'YYYY-MM-DD HH:mm:ss' + }), + fileFormatter + ); + const logFilePath = path.isAbsolute(process.env.VSC_PYTHON_LOG_FILE) + ? process.env.VSC_PYTHON_LOG_FILE + : path.join(EXTENSION_ROOT_DIR, process.env.VSC_PYTHON_LOG_FILE); + const logFileSink = new transports.File({ + format: fileFormat, + filename: logFilePath, + handleExceptions: true + }); + fileLogger.add(logFileSink); +} From aa001a0e38dd609f7bed3e9f70beccff828d90ee Mon Sep 17 00:00:00 2001 From: Eric Snow Date: Tue, 14 Apr 2020 12:48:02 -0600 Subject: [PATCH 05/13] Move the "trace" logging code to a dedicated module. --- src/client/common/logger.ts | 2 +- src/client/logging/_trace.ts | 110 ++++++++++++++++++++++++++++++++++ src/client/logging/index.ts | 113 +++-------------------------------- 3 files changed, 119 insertions(+), 106 deletions(-) create mode 100644 src/client/logging/_trace.ts diff --git a/src/client/common/logger.ts b/src/client/common/logger.ts index fdce6b295fb8..7d0a61a676e1 100644 --- a/src/client/common/logger.ts +++ b/src/client/common/logger.ts @@ -5,5 +5,5 @@ export { traceInfo, traceVerbose, traceWarning -} from '../logging'; +} from '../logging/_trace'; export { TraceOptions as LogOptions } from '../logging/types'; 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/index.ts b/src/client/logging/index.ts index 41a8c545ff82..081b4a21f0ae 100644 --- a/src/client/logging/index.ts +++ b/src/client/logging/index.ts @@ -2,108 +2,11 @@ // 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; - }; -} +export { + // aliases + traceDecorators, + traceError, + traceInfo, + traceVerbose, + traceWarning +} from './_trace'; From 8cc35d3a5175bcc1377e4b318bbeb4a503880cfe Mon Sep 17 00:00:00 2001 From: Eric Snow Date: Tue, 14 Apr 2020 12:57:58 -0600 Subject: [PATCH 06/13] Factor out normalizeLevel(). --- src/client/logging/logger.ts | 18 ++++++++++++------ 1 file changed, 12 insertions(+), 6 deletions(-) diff --git a/src/client/logging/logger.ts b/src/client/logging/logger.ts index 0fde9f5e3315..becc46b00392 100644 --- a/src/client/logging/logger.ts +++ b/src/client/logging/logger.ts @@ -45,6 +45,14 @@ function logToFile(logLevel: LogLevel, ...args: any[]) { fileLogger.log(logLevelMap[logLevel], message); } +// 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. +function normalizeLevel(level: string): string { + return `${level.substring(0, 1).toUpperCase()}${level.substring(1)}`; +} + /** * Initialize the logger for console. * We do two things here: @@ -147,11 +155,9 @@ function initializeConsoleLogger() { } } const consoleFormatter = format.printf(({ level, message, label, timestamp }) => { + level = normalizeLevel(level); // If we're on CI server, no need for the label (prefix) - // Pascal casing og log level, so log files get highlighted when viewing in VSC and other editors. - const prefix = `${level.substring(0, 1).toUpperCase()}${level.substring(1)} ${ - process.env.TF_BUILD ? '' : label - }`; + const prefix = `${level} ${process.env.TF_BUILD ? '' : label}`; return `${prefix.trim()} ${timestamp}: ${message}`; }); const consoleFormat = format.combine( @@ -174,8 +180,8 @@ function initializeFileLogger() { return; } const fileFormatter = format.printf(({ level, message, timestamp }) => { - // Pascal casing og log level, so log files get highlighted when viewing in VSC and other editors. - return `${level.substring(0, 1).toUpperCase()}${level.substring(1)} ${timestamp}: ${message}`; + level = normalizeLevel(level); + return `${level} ${timestamp}: ${message}`; }); const fileFormat = format.combine( format.timestamp({ From 972c96014e4dc48c797fa1e7c743123d4c0a99d3 Mon Sep 17 00:00:00 2001 From: Eric Snow Date: Tue, 14 Apr 2020 13:08:44 -0600 Subject: [PATCH 07/13] Factor out formatMessage() and formatLabeledMessage(). --- src/client/logging/logger.ts | 28 ++++++++++++++++++++-------- 1 file changed, 20 insertions(+), 8 deletions(-) diff --git a/src/client/logging/logger.ts b/src/client/logging/logger.ts index becc46b00392..7fe27466fd64 100644 --- a/src/client/logging/logger.ts +++ b/src/client/logging/logger.ts @@ -53,6 +53,16 @@ function normalizeLevel(level: string): string { return `${level.substring(0, 1).toUpperCase()}${level.substring(1)}`; } +function formatMessage(level: string, timestamp: string, message: string): string { + level = normalizeLevel(level); + return `${level} ${timestamp}: ${message}`; +} + +function formatLabeledMessage(level: string, timestamp: string, label: string, message: string): string { + level = normalizeLevel(level); + return `${level} ${label} ${timestamp}: ${message}`; +} + /** * Initialize the logger for console. * We do two things here: @@ -155,10 +165,12 @@ function initializeConsoleLogger() { } } const consoleFormatter = format.printf(({ level, message, label, timestamp }) => { - level = normalizeLevel(level); - // If we're on CI server, no need for the label (prefix) - const prefix = `${level} ${process.env.TF_BUILD ? '' : label}`; - return `${prefix.trim()} ${timestamp}: ${message}`; + if (process.env.TF_BUILD) { + // In CI there's no need for the label. + return formatMessage(level, timestamp, message); + } else { + return formatLabeledMessage(level, timestamp, label, message); + } }); const consoleFormat = format.combine( format.label({ label: 'Python Extension:' }), @@ -179,10 +191,10 @@ function initializeFileLogger() { if (!process.env.VSC_PYTHON_LOG_FILE) { return; } - const fileFormatter = format.printf(({ level, message, timestamp }) => { - level = normalizeLevel(level); - return `${level} ${timestamp}: ${message}`; - }); + const fileFormatter = format.printf( + // a minimal format + ({ level, message, timestamp }) => formatMessage(level, timestamp, message) + ); const fileFormat = format.combine( format.timestamp({ format: 'YYYY-MM-DD HH:mm:ss' From 5434e7e3d6d2648681f92e9ace3cd99d02588049 Mon Sep 17 00:00:00 2001 From: Eric Snow Date: Tue, 14 Apr 2020 13:22:49 -0600 Subject: [PATCH 08/13] Factor out getFormatter() and getLabeledFormatter(). --- src/client/logging/logger.ts | 53 +++++++++++++++++++----------------- 1 file changed, 28 insertions(+), 25 deletions(-) diff --git a/src/client/logging/logger.ts b/src/client/logging/logger.ts index 7fe27466fd64..7281102709a3 100644 --- a/src/client/logging/logger.ts +++ b/src/client/logging/logger.ts @@ -63,6 +63,29 @@ function formatLabeledMessage(level: string, timestamp: string, label: string, m return `${level} ${label} ${timestamp}: ${message}`; } +const TIMESTAMP = 'YYYY-MM-DD HH:mm:ss'; + +function getFormatter() { + return format.combine( + format.timestamp({ format: TIMESTAMP }), + format.printf( + // a minimal message + ({ level, message, timestamp }) => formatMessage(level, timestamp, message) + ) + ); +} + +function getLabeledFormatter(label_: string) { + return format.combine( + format.label({ label: label_ }), + format.timestamp({ format: TIMESTAMP }), + format.printf( + // mostly a minimal message + ({ level, message, label, timestamp }) => formatLabeledMessage(level, timestamp, label, message) + ) + ); +} + /** * Initialize the logger for console. * We do two things here: @@ -164,22 +187,12 @@ function initializeConsoleLogger() { } } } - const consoleFormatter = format.printf(({ level, message, label, timestamp }) => { - if (process.env.TF_BUILD) { + consoleLogger.add( + new ConsoleTransport({ // In CI there's no need for the label. - return formatMessage(level, timestamp, message); - } else { - return formatLabeledMessage(level, timestamp, label, message); - } - }); - const consoleFormat = format.combine( - format.label({ label: 'Python Extension:' }), - format.timestamp({ - format: 'YYYY-MM-DD HH:mm:ss' - }), - consoleFormatter + format: process.env.TF_BUILD ? getFormatter() : getLabeledFormatter('Python Extension:') + }) as any ); - consoleLogger.add(new ConsoleTransport({ format: consoleFormat }) as any); } /** @@ -191,21 +204,11 @@ function initializeFileLogger() { if (!process.env.VSC_PYTHON_LOG_FILE) { return; } - const fileFormatter = format.printf( - // a minimal format - ({ level, message, timestamp }) => formatMessage(level, timestamp, message) - ); - const fileFormat = format.combine( - format.timestamp({ - format: 'YYYY-MM-DD HH:mm:ss' - }), - fileFormatter - ); const logFilePath = path.isAbsolute(process.env.VSC_PYTHON_LOG_FILE) ? process.env.VSC_PYTHON_LOG_FILE : path.join(EXTENSION_ROOT_DIR, process.env.VSC_PYTHON_LOG_FILE); const logFileSink = new transports.File({ - format: fileFormat, + format: getFormatter(), filename: logFilePath, handleExceptions: true }); From 53c91f843a8f721b8c0273efa99fe4d84814a030 Mon Sep 17 00:00:00 2001 From: Eric Snow Date: Tue, 14 Apr 2020 13:36:18 -0600 Subject: [PATCH 09/13] Move the formatter code to a dedicated module. --- src/client/logging/formatters.ts | 61 ++++++++++++++++++++++++++++++++ src/client/logging/logger.ts | 46 ++---------------------- src/client/logging/types.ts | 5 +++ 3 files changed, 69 insertions(+), 43 deletions(-) create mode 100644 src/client/logging/formatters.ts diff --git a/src/client/logging/formatters.ts b/src/client/logging/formatters.ts new file mode 100644 index 000000000000..1867186d09c2 --- /dev/null +++ b/src/client/logging/formatters.ts @@ -0,0 +1,61 @@ +// Copyright (c) Microsoft Corporation. All rights reserved. +// Licensed under the MIT License. +'use strict'; + +import { format } from 'winston'; +import { FormatterOptions } from './types'; + +const TIMESTAMP = 'YYYY-MM-DD HH:mm:ss'; + +// 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. +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: 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: 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" +// logging transport. +function getMinimalFormatter() { + return format.combine( + format.timestamp({ format: TIMESTAMP }), + format.printf( + // a minimal message + ({ level, message, timestamp }) => formatMessage(level, timestamp, message) + ) + ); +} + +// Return a minimal format object that can be used with a "winston" +// logging transport. +function getLabeledFormatter(label_: string) { + return format.combine( + format.label({ label: label_ }), + format.timestamp({ format: TIMESTAMP }), + format.printf( + // mostly a minimal message + ({ level, message, label, timestamp }) => formatLabeledMessage(level, timestamp, label, message) + ) + ); +} + +// Return a format object that can be used with a "winston" logging transport. +export function getFormatter(opts: FormatterOptions = {}) { + if (opts.label) { + return getLabeledFormatter(opts.label); + } + return getMinimalFormatter(); +} diff --git a/src/client/logging/logger.ts b/src/client/logging/logger.ts index 7281102709a3..8ca23918f8ec 100644 --- a/src/client/logging/logger.ts +++ b/src/client/logging/logger.ts @@ -6,9 +6,10 @@ import * as path from 'path'; import * as util from 'util'; -import { createLogger, format, transports } from 'winston'; +import { createLogger, transports } from 'winston'; import { isTestExecution } from '../common/constants'; import { EXTENSION_ROOT_DIR } from '../constants'; +import { getFormatter } from './formatters'; import { LogLevel } from './types'; // tslint:disable-next-line: no-var-requires no-require-imports @@ -45,47 +46,6 @@ function logToFile(logLevel: LogLevel, ...args: any[]) { fileLogger.log(logLevelMap[logLevel], message); } -// 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. -function normalizeLevel(level: string): string { - return `${level.substring(0, 1).toUpperCase()}${level.substring(1)}`; -} - -function formatMessage(level: string, timestamp: string, message: string): string { - level = normalizeLevel(level); - return `${level} ${timestamp}: ${message}`; -} - -function formatLabeledMessage(level: string, timestamp: string, label: string, message: string): string { - level = normalizeLevel(level); - return `${level} ${label} ${timestamp}: ${message}`; -} - -const TIMESTAMP = 'YYYY-MM-DD HH:mm:ss'; - -function getFormatter() { - return format.combine( - format.timestamp({ format: TIMESTAMP }), - format.printf( - // a minimal message - ({ level, message, timestamp }) => formatMessage(level, timestamp, message) - ) - ); -} - -function getLabeledFormatter(label_: string) { - return format.combine( - format.label({ label: label_ }), - format.timestamp({ format: TIMESTAMP }), - format.printf( - // mostly a minimal message - ({ level, message, label, timestamp }) => formatLabeledMessage(level, timestamp, label, message) - ) - ); -} - /** * Initialize the logger for console. * We do two things here: @@ -190,7 +150,7 @@ function initializeConsoleLogger() { consoleLogger.add( new ConsoleTransport({ // In CI there's no need for the label. - format: process.env.TF_BUILD ? getFormatter() : getLabeledFormatter('Python Extension:') + format: getFormatter({ label: process.env.TF_BUILD ? undefined : 'Python Extension:' }) }) as any ); } diff --git a/src/client/logging/types.ts b/src/client/logging/types.ts index b477945a6bfd..adb415566daa 100644 --- a/src/client/logging/types.ts +++ b/src/client/logging/types.ts @@ -9,6 +9,11 @@ export enum LogLevel { Information = 2 } +// Knobs used when creating a formatter. +export type FormatterOptions = { + label?: string; +}; + // The information we want to log. export enum TraceOptions { None = 0, From 7848c2db9bd546ae00e521162c68d3b2cdc1968d Mon Sep 17 00:00:00 2001 From: Eric Snow Date: Tue, 14 Apr 2020 14:02:37 -0600 Subject: [PATCH 10/13] Factor out getConsoleTransport() and getFileTransport(). --- src/client/logging/logger.ts | 90 +++++++++++++++++++++--------------- 1 file changed, 52 insertions(+), 38 deletions(-) diff --git a/src/client/logging/logger.ts b/src/client/logging/logger.ts index 8ca23918f8ec..dc009fe78083 100644 --- a/src/client/logging/logger.ts +++ b/src/client/logging/logger.ts @@ -4,6 +4,7 @@ // tslint:disable:no-console no-any +import * as logform from 'logform'; import * as path from 'path'; import * as util from 'util'; import { createLogger, transports } from 'winston'; @@ -46,6 +47,23 @@ function logToFile(logLevel: LogLevel, ...args: any[]) { fileLogger.log(logLevelMap[logLevel], message); } +const logMethods = { + log: Symbol.for('log'), + info: Symbol.for('info'), + error: Symbol.for('error'), + debug: Symbol.for('debug'), + warn: Symbol.for('warn') +}; + +function logToConsole(stream: 'info' | 'error' | 'warn' | 'log' | 'debug', ...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); +} + /** * Initialize the logger for console. * We do two things here: @@ -63,23 +81,6 @@ function logToFile(logLevel: LogLevel, ...args: any[]) { */ // tslint:disable-next-line: max-func-body-length function initializeConsoleLogger() { - const logMethods = { - log: Symbol.for('log'), - info: Symbol.for('info'), - error: Symbol.for('error'), - debug: Symbol.for('debug'), - warn: Symbol.for('warn') - }; - - function logToConsole(stream: 'info' | 'error' | 'warn' | 'log' | 'debug', ...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); - } - // Hijack `console.log` when running tests on CI. if (process.env.VSC_PYTHON_LOG_FILE && process.env.TF_BUILD) { /* @@ -134,6 +135,30 @@ function initializeConsoleLogger() { // 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(formatter); + consoleLogger.add(transport as any); +} + +/** + * 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); +} + +function getConsoleTransport(formatter: logform.Format) { const formattedMessage = Symbol.for('message'); class ConsoleTransport extends TransportStream { constructor(options?: any) { @@ -147,30 +172,19 @@ function initializeConsoleLogger() { } } } - consoleLogger.add( - new ConsoleTransport({ - // In CI there's no need for the label. - format: getFormatter({ label: process.env.TF_BUILD ? undefined : 'Python Extension:' }) - }) as any - ); + return new ConsoleTransport({ + // We minimize customization. + format: formatter + }); } -/** - * 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() { - if (!process.env.VSC_PYTHON_LOG_FILE) { - return; +function getFileTransport(logfile: string, formatter: logform.Format) { + if (!path.isAbsolute(logfile)) { + logfile = path.join(EXTENSION_ROOT_DIR, logfile); } - const logFilePath = path.isAbsolute(process.env.VSC_PYTHON_LOG_FILE) - ? process.env.VSC_PYTHON_LOG_FILE - : path.join(EXTENSION_ROOT_DIR, process.env.VSC_PYTHON_LOG_FILE); - const logFileSink = new transports.File({ - format: getFormatter(), - filename: logFilePath, + return new transports.File({ + format: formatter, + filename: logfile, handleExceptions: true }); - fileLogger.add(logFileSink); } From a7c133da4f19637a407dcdc2d76373697bbdab10 Mon Sep 17 00:00:00 2001 From: Eric Snow Date: Tue, 14 Apr 2020 14:25:24 -0600 Subject: [PATCH 11/13] Move the transport code to a dedicated module. --- src/client/logging/logger.ts | 46 ++++------------------------- src/client/logging/transports.ts | 50 ++++++++++++++++++++++++++++++++ src/client/logging/types.ts | 3 ++ 3 files changed, 58 insertions(+), 41 deletions(-) create mode 100644 src/client/logging/transports.ts diff --git a/src/client/logging/logger.ts b/src/client/logging/logger.ts index dc009fe78083..533dde0c3ce0 100644 --- a/src/client/logging/logger.ts +++ b/src/client/logging/logger.ts @@ -4,17 +4,12 @@ // tslint:disable:no-console no-any -import * as logform from 'logform'; -import * as path from 'path'; import * as util from 'util'; -import { createLogger, transports } from 'winston'; +import { createLogger } from 'winston'; import { isTestExecution } from '../common/constants'; -import { EXTENSION_ROOT_DIR } from '../constants'; import { getFormatter } from './formatters'; -import { LogLevel } from './types'; - -// tslint:disable-next-line: no-var-requires no-require-imports -const TransportStream = require('winston-transport'); +import { getConsoleTransport, getFileTransport } from './transports'; +import { ConsoleStreams, LogLevel } from './types'; // Initialize the loggers as soon as this module is imported. const consoleLogger = createLogger(); @@ -55,7 +50,7 @@ const logMethods = { warn: Symbol.for('warn') }; -function logToConsole(stream: 'info' | 'error' | 'warn' | 'log' | 'debug', ...args: any[]) { +function logToConsole(stream: ConsoleStreams, ...args: any[]) { if (['info', 'error', 'warn', 'log', 'debug'].indexOf(stream) === -1) { stream = 'log'; } @@ -139,7 +134,7 @@ function initializeConsoleLogger() { // In CI there's no need for the label. label: process.env.TF_BUILD ? undefined : 'Python Extension:' }); - const transport = getConsoleTransport(formatter); + const transport = getConsoleTransport(logToConsole, formatter); consoleLogger.add(transport as any); } @@ -157,34 +152,3 @@ function initializeFileLogger() { const transport = getFileTransport(logfile, formatter); fileLogger.add(transport); } - -function getConsoleTransport(formatter: logform.Format) { - const formattedMessage = Symbol.for('message'); - class ConsoleTransport extends TransportStream { - constructor(options?: any) { - super(options); - } - 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(); - } - } - } - return new ConsoleTransport({ - // We minimize customization. - format: formatter - }); -} - -function getFileTransport(logfile: string, formatter: logform.Format) { - if (!path.isAbsolute(logfile)) { - logfile = path.join(EXTENSION_ROOT_DIR, logfile); - } - return new transports.File({ - format: formatter, - filename: logfile, - handleExceptions: true - }); -} diff --git a/src/client/logging/transports.ts b/src/client/logging/transports.ts new file mode 100644 index 000000000000..03b779b5ce33 --- /dev/null +++ b/src/client/logging/transports.ts @@ -0,0 +1,50 @@ +// Copyright (c) Microsoft Corporation. All rights reserved. +// 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 { EXTENSION_ROOT_DIR } from '../constants'; +import { ConsoleStreams } from './types'; + +// tslint:disable-next-line: no-var-requires no-require-imports +const TransportStream = require('winston-transport'); + +// 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); + } + 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(); + } + } + } + return new ConsoleTransport({ + // We minimize customization. + format: formatter + }); +} + +// Create a file-targeting transport that can be added to a winston logger. +export function getFileTransport(logfile: string, formatter: logform.Format) { + if (!path.isAbsolute(logfile)) { + logfile = path.join(EXTENSION_ROOT_DIR, logfile); + } + return new transports.File({ + format: formatter, + filename: logfile, + handleExceptions: true + }); +} diff --git a/src/client/logging/types.ts b/src/client/logging/types.ts index adb415566daa..d769bff5e189 100644 --- a/src/client/logging/types.ts +++ b/src/client/logging/types.ts @@ -9,6 +9,9 @@ export enum LogLevel { 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; From 46993d6ddcca2fca107df5ba98e526905b50198e Mon Sep 17 00:00:00 2001 From: Eric Snow Date: Tue, 14 Apr 2020 14:42:41 -0600 Subject: [PATCH 12/13] Move the console-related code to a dedicated module. --- src/client/logging/_console.ts | 74 ++++++++++++++++++++++++++++++++++ src/client/logging/logger.ts | 67 ++---------------------------- 2 files changed, 78 insertions(+), 63 deletions(-) create mode 100644 src/client/logging/_console.ts 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/logger.ts b/src/client/logging/logger.ts index 533dde0c3ce0..55246130a738 100644 --- a/src/client/logging/logger.ts +++ b/src/client/logging/logger.ts @@ -2,14 +2,15 @@ // Licensed under the MIT License. 'use strict'; -// tslint:disable:no-console no-any +// tslint:disable:no-any import * as util from 'util'; import { createLogger } from 'winston'; import { isTestExecution } from '../common/constants'; +import { logToConsole, monkeypatchConsole } from './_console'; import { getFormatter } from './formatters'; import { getConsoleTransport, getFileTransport } from './transports'; -import { ConsoleStreams, LogLevel } from './types'; +import { LogLevel } from './types'; // Initialize the loggers as soon as this module is imported. const consoleLogger = createLogger(); @@ -42,23 +43,6 @@ function logToFile(logLevel: LogLevel, ...args: any[]) { fileLogger.log(logLevelMap[logLevel], message); } -const logMethods = { - log: Symbol.for('log'), - info: Symbol.for('info'), - error: Symbol.for('error'), - debug: Symbol.for('debug'), - warn: Symbol.for('warn') -}; - -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); -} - /** * Initialize the logger for console. * We do two things here: @@ -74,53 +58,10 @@ function logToConsole(stream: ConsoleStreams, ...args: any[]) { * To do this we need to monkey patch the console methods. * This is optional (generally done when running tests on CI). */ -// tslint:disable-next-line: max-func-body-length function initializeConsoleLogger() { // Hijack `console.log` when running tests on CI. if (process.env.VSC_PYTHON_LOG_FILE && process.env.TF_BUILD) { - /* - 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). - */ - // 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); - }; + monkeypatchConsole(logToFile); } if (isTestExecution() && !process.env.VSC_PYTHON_FORCE_LOGGING) { From af60cfddba95761cb7c92c9af6e96c8d4ffceed4 Mon Sep 17 00:00:00 2001 From: Eric Snow Date: Tue, 5 May 2020 11:59:30 -0600 Subject: [PATCH 13/13] Add comments to explain the purpose of the logging aliases. --- src/client/common/logger.ts | 1 + src/client/logging/index.ts | 1 + 2 files changed, 2 insertions(+) diff --git a/src/client/common/logger.ts b/src/client/common/logger.ts index 7d0a61a676e1..f43a633ffd45 100644 --- a/src/client/common/logger.ts +++ b/src/client/common/logger.ts @@ -1,5 +1,6 @@ export { // aliases: + // (temporarily for backward compatibility and to avoid churn) traceDecorators, traceError, traceInfo, diff --git a/src/client/logging/index.ts b/src/client/logging/index.ts index 081b4a21f0ae..6da41c569a13 100644 --- a/src/client/logging/index.ts +++ b/src/client/logging/index.ts @@ -4,6 +4,7 @@ export { // aliases + // (for convenience) traceDecorators, traceError, traceInfo,