diff --git a/src/client/common/logger.ts b/src/client/common/logger.ts index 4f4979fe04a0..f43a633ffd45 100644 --- a/src/client/common/logger.ts +++ b/src/client/common/logger.ts @@ -1,339 +1,10 @@ -// 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: + // (temporarily for backward compatibility and to avoid churn) + traceDecorators, + traceError, + traceInfo, + traceVerbose, + traceWarning +} from '../logging/_trace'; +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/_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/_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 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/index.ts b/src/client/logging/index.ts new file mode 100644 index 000000000000..6da41c569a13 --- /dev/null +++ b/src/client/logging/index.ts @@ -0,0 +1,13 @@ +// Copyright (c) Microsoft Corporation. All rights reserved. +// Licensed under the MIT License. +'use strict'; + +export { + // aliases + // (for convenience) + traceDecorators, + traceError, + traceInfo, + traceVerbose, + traceWarning +} from './_trace'; diff --git a/src/client/logging/logger.ts b/src/client/logging/logger.ts new file mode 100644 index 000000000000..55246130a738 --- /dev/null +++ b/src/client/logging/logger.ts @@ -0,0 +1,95 @@ +// Copyright (c) Microsoft Corporation. All rights reserved. +// Licensed under the MIT License. +'use strict'; + +// tslint:disable:no-any + +import * as util from 'util'; +import { createLogger } from 'winston'; +import { isTestExecution } from '../common/constants'; +import { logToConsole, monkeypatchConsole } from './_console'; +import { getFormatter } from './formatters'; +import { getConsoleTransport, getFileTransport } from './transports'; +import { LogLevel } from './types'; + +// Initialize the loggers as soon as this module is imported. +const consoleLogger = createLogger(); +const fileLogger = createLogger(); +initializeConsoleLogger(); +initializeFileLogger(); + +// 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). + */ +function initializeConsoleLogger() { + // Hijack `console.log` when running tests on CI. + if (process.env.VSC_PYTHON_LOG_FILE && process.env.TF_BUILD) { + monkeypatchConsole(logToFile); + } + + 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 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); +} + +/** + * 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/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 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 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}`; + } +}