From fe1a91a234281263014323ffe123849048d8386b Mon Sep 17 00:00:00 2001 From: Kartik Raj Date: Thu, 4 Jun 2020 23:00:38 +0530 Subject: [PATCH] Monkeypatch console.* calls on CI if we are asked to (#11897) * Move console.* monkeypatching to src/test/testLogging.ts * Use monkeypatching in all tests launched using testBootstrap.ts * Use monkeypatching in single workspace and multiroot tests * News entry * Don't do monkeypatching for smoketests * Modify gulp task to not delete 'out/client/logging' directory * Undo smoke test ccheck * Import only from ./out/client/logging in test logger * Added comment * More corrections * Add comments * Correct smoke tests * Oops --- build/ci/templates/test_phases.yml | 5 ++- news/3 Code Health/11896.md | 1 + src/client/logging/_global.ts | 67 +----------------------------- src/client/logging/levels.ts | 3 ++ src/client/logging/logger.ts | 31 ++++++++++++++ src/client/logging/transports.ts | 14 +++++-- src/test/index.ts | 3 ++ src/test/multiRootTest.ts | 3 ++ src/test/performanceTest.ts | 3 ++ src/test/standardTest.ts | 3 ++ src/test/testBootstrap.ts | 3 ++ src/test/testLogger.ts | 59 ++++++++++++++++++++++++++ 12 files changed, 125 insertions(+), 70 deletions(-) create mode 100644 news/3 Code Health/11896.md create mode 100644 src/test/testLogger.ts diff --git a/build/ci/templates/test_phases.yml b/build/ci/templates/test_phases.yml index 3e5ba2a6c45c..b5ca77e10bde 100644 --- a/build/ci/templates/test_phases.yml +++ b/build/ci/templates/test_phases.yml @@ -518,12 +518,15 @@ steps: npm install -g vsce npm run clean npx tsc -p ./ + mkdir -p ./tmp/client/logging + cp -r ./out/client/logging ./tmp/client npx gulp clean:cleanExceptTests - mkdir -p ./tmp cp -r ./out/test ./tmp/test npm run updateBuildNumber -- --buildNumber $BUILD_BUILDID npm run package npx gulp clean:cleanExceptTests + mkdir -p ./out/client/logging + cp -r ./tmp/client/logging ./out/client cp -r ./tmp/test ./out/test node --no-force-async-hooks-checks ./out/test/smokeTest.js displayName: 'Run Smoke Tests' diff --git a/news/3 Code Health/11896.md b/news/3 Code Health/11896.md new file mode 100644 index 000000000000..5835aacebeaa --- /dev/null +++ b/news/3 Code Health/11896.md @@ -0,0 +1 @@ +Monkeypatch `console.*` calls to the logger only in CI. diff --git a/src/client/logging/_global.ts b/src/client/logging/_global.ts index 6c1b03743da8..dabd864551f3 100644 --- a/src/client/logging/_global.ts +++ b/src/client/logging/_global.ts @@ -3,12 +3,11 @@ 'use strict'; import * as winston from 'winston'; -import { isCI } from '../common/constants'; import { IOutputChannel } from '../common/types'; import { CallInfo } from '../common/utils/decorators'; import { getFormatter } from './formatters'; import { LogLevel, resolveLevelName } from './levels'; -import { configureLogger, createLogger, ILogger, LoggerConfig, logToAll } from './logger'; +import { configureLogger, createLogger, getPreDefinedConfiguration, logToAll } from './logger'; import { createTracingDecorator, LogInfo, TraceOptions, tracing as _tracing } from './trace'; import { getPythonOutputChannelTransport } from './transports'; import { Arguments } from './util'; @@ -40,35 +39,7 @@ initialize(); * this is setup on CI servers. */ function initialize() { - const config: LoggerConfig = {}; - let nonConsole = false; - - // Do not log to console if running tests and we're not - // asked to do so. - if (process.env.VSC_PYTHON_FORCE_LOGGING) { - config.console = {}; - // In CI there's no need for the label. - if (!isCI) { - config.console.label = 'Python Extension:'; - } - } - if (process.env.VSC_PYTHON_LOG_FILE) { - config.file = { - logfile: process.env.VSC_PYTHON_LOG_FILE - }; - nonConsole = true; - } - configureLogger(globalLogger, config); - - if (isCI && nonConsole) { - delete config.console; - // Send console.*() to the non-console loggers. - monkeypatchConsole( - // This is a separate logger that matches our config but - // does not do any console logging. - createLogger(config) - ); - } + configureLogger(globalLogger, getPreDefinedConfiguration()); } // Set the logging level the extension logs at. @@ -144,37 +115,3 @@ export namespace traceDecorators { return createTracingDecorator([globalLogger], { message, opts, level }); } } - -/** - * What we're doing here is monkey patching the console.log so we can - * send everything sent to console window into our logs. This is only - * required when we're directly writing to `console.log` or not using - * our `winston logger`. This is something we'd generally turn on, only - * on CI so we can see everything logged to the console window - * (via the logs). - */ -function monkeypatchConsole(logger: ILogger) { - // The logging "streams" (methods) of the node console. - const streams = ['log', 'error', 'warn', 'info', 'debug', 'trace']; - const levels: { [key: string]: LogLevel } = { - error: LogLevel.Error, - warn: LogLevel.Warn - }; - // tslint:disable-next-line:no-any - const consoleAny: any = console; - for (const stream of streams) { - // Using symbols guarantee the properties will be unique & prevents - // clashing with names other code/library may create or have created. - // We could use a closure but it's a bit trickier. - const sym = Symbol.for(stream); - consoleAny[sym] = consoleAny[stream]; - // tslint:disable-next-line: no-function-expression - consoleAny[stream] = function () { - const args = Array.prototype.slice.call(arguments); - const fn = consoleAny[sym]; - fn(...args); - const level = levels[stream] || LogLevel.Info; - logToAll([logger], level, args); - }; - } -} diff --git a/src/client/logging/levels.ts b/src/client/logging/levels.ts index d857946a6c75..c0982dd3c282 100644 --- a/src/client/logging/levels.ts +++ b/src/client/logging/levels.ts @@ -2,6 +2,9 @@ // Licensed under the MIT License. 'use strict'; +// IMPORTANT: This file should only be importing from the '../client/logging' directory, as we +// delete everything in '../client' except for '../client/logging' before running smoke tests. + import * as winston from 'winston'; //====================== diff --git a/src/client/logging/logger.ts b/src/client/logging/logger.ts index f6d29e83b9b9..ab5ba55cb519 100644 --- a/src/client/logging/logger.ts +++ b/src/client/logging/logger.ts @@ -2,6 +2,9 @@ // Licensed under the MIT License. 'use strict'; +// IMPORTANT: This file should only be importing from the '../client/logging' directory, as we +// delete everything in '../client' except for '../client/logging' before running smoke tests. + import * as util from 'util'; import * as winston from 'winston'; import * as Transport from 'winston-transport'; @@ -36,6 +39,34 @@ interface IConfigurableLogger { add(transport: Transport): void; } +// tslint:disable-next-line: no-suspicious-comment +/** + * TODO: We should actually have this method in `./_global.ts` as this is exported globally. + * But for some reason, importing '../client/logging/_global' fails when launching the tests. + * More details in the comment https://github.com/microsoft/vscode-python/pull/11897#discussion_r433954993 + * https://github.com/microsoft/vscode-python/issues/12137 + */ +export function getPreDefinedConfiguration(): LoggerConfig { + const config: LoggerConfig = {}; + + // Do not log to console if running tests and we're not + // asked to do so. + if (process.env.VSC_PYTHON_FORCE_LOGGING) { + config.console = {}; + // In CI there's no need for the label. + const isCI = process.env.TRAVIS === 'true' || process.env.TF_BUILD !== undefined; + if (!isCI) { + config.console.label = 'Python Extension:'; + } + } + if (process.env.VSC_PYTHON_LOG_FILE) { + config.file = { + logfile: process.env.VSC_PYTHON_LOG_FILE + }; + } + return config; +} + // Set up a logger just the way we like it. export function configureLogger(logger: IConfigurableLogger, config: LoggerConfig) { if (config.level) { diff --git a/src/client/logging/transports.ts b/src/client/logging/transports.ts index 825199eae55e..2a8e83a5fa52 100644 --- a/src/client/logging/transports.ts +++ b/src/client/logging/transports.ts @@ -2,15 +2,21 @@ // Licensed under the MIT License. 'use strict'; +// IMPORTANT: This file should only be importing from the '../client/logging' directory, as we +// delete everything in '../client' except for '../client/logging' before running smoke tests. + import * as logform from 'logform'; import * as path from 'path'; +import { OutputChannel } from 'vscode'; import * as winston from 'winston'; import * as Transport from 'winston-transport'; -import { IOutputChannel } from '../common/types'; -import { EXTENSION_ROOT_DIR } from '../constants'; import { LogLevel, resolveLevel } from './levels'; import { Arguments } from './util'; +const folderPath = path.dirname(__dirname); +const folderName = path.basename(folderPath); +const EXTENSION_ROOT_DIR = + folderName === 'client' ? path.join(folderPath, '..', '..') : path.join(folderPath, '..', '..', '..', '..'); const formattedMessage = Symbol.for('message'); export function isConsoleTransport(transport: unknown): boolean { @@ -74,7 +80,7 @@ export function getConsoleTransport(formatter: logform.Format): Transport { class PythonOutputChannelTransport extends Transport { // tslint:disable-next-line: no-any - constructor(private readonly channel: IOutputChannel, options?: any) { + constructor(private readonly channel: OutputChannel, options?: any) { super(options); } // tslint:disable-next-line: no-any @@ -88,7 +94,7 @@ class PythonOutputChannelTransport extends Transport { } // Create a Python output channel targeting transport that can be added to a winston logger. -export function getPythonOutputChannelTransport(channel: IOutputChannel, formatter: logform.Format) { +export function getPythonOutputChannelTransport(channel: OutputChannel, formatter: logform.Format) { return new PythonOutputChannelTransport(channel, { // We minimize customization. format: formatter diff --git a/src/test/index.ts b/src/test/index.ts index 524d1c6aa616..d8d5a7324540 100644 --- a/src/test/index.ts +++ b/src/test/index.ts @@ -23,6 +23,9 @@ import { TEST_TIMEOUT } from './constants'; import { initialize } from './initialize'; +import { initializeLogger } from './testLogger'; + +initializeLogger(); type SetupOptions = Mocha.MochaOptions & { testFilesSuffix: string; diff --git a/src/test/multiRootTest.ts b/src/test/multiRootTest.ts index 402d8c60db73..5859708a8e99 100644 --- a/src/test/multiRootTest.ts +++ b/src/test/multiRootTest.ts @@ -3,11 +3,14 @@ import * as path from 'path'; import { runTests } from 'vscode-test'; import { EXTENSION_ROOT_DIR_FOR_TESTS } from './constants'; +import { initializeLogger } from './testLogger'; const workspacePath = path.join(__dirname, '..', '..', 'src', 'testMultiRootWkspc', 'multi.code-workspace'); process.env.IS_CI_SERVER_TEST_DEBUGGER = ''; process.env.VSC_PYTHON_CI_TEST = '1'; +initializeLogger(); + function start() { console.log('*'.repeat(100)); console.log('Start Multiroot tests'); diff --git a/src/test/performanceTest.ts b/src/test/performanceTest.ts index dbc02cc3652c..938630943570 100644 --- a/src/test/performanceTest.ts +++ b/src/test/performanceTest.ts @@ -25,6 +25,9 @@ import * as request from 'request'; import { LanguageServerType } from '../client/activation/types'; import { EXTENSION_ROOT_DIR, PVSC_EXTENSION_ID } from '../client/common/constants'; import { unzip } from './common'; +import { initializeLogger } from './testLogger'; + +initializeLogger(); const NamedRegexp = require('named-js-regexp'); const del = require('del'); diff --git a/src/test/standardTest.ts b/src/test/standardTest.ts index a875f1fcf814..f35cb42126d4 100644 --- a/src/test/standardTest.ts +++ b/src/test/standardTest.ts @@ -3,6 +3,9 @@ import * as path from 'path'; import { runTests } from 'vscode-test'; import { EXTENSION_ROOT_DIR_FOR_TESTS } from './constants'; +import { initializeLogger } from './testLogger'; + +initializeLogger(); process.env.IS_CI_SERVER_TEST_DEBUGGER = ''; process.env.VSC_PYTHON_CI_TEST = '1'; diff --git a/src/test/testBootstrap.ts b/src/test/testBootstrap.ts index 905f3fdf45b7..06d65d41f8fe 100644 --- a/src/test/testBootstrap.ts +++ b/src/test/testBootstrap.ts @@ -9,6 +9,9 @@ import { AddressInfo, createServer, Server } from 'net'; import * as path from 'path'; import { EXTENSION_ROOT_DIR } from '../client/constants'; import { noop, sleep } from './core'; +import { initializeLogger } from './testLogger'; + +initializeLogger(); // tslint:disable:no-console diff --git a/src/test/testLogger.ts b/src/test/testLogger.ts new file mode 100644 index 000000000000..5090e23d1faf --- /dev/null +++ b/src/test/testLogger.ts @@ -0,0 +1,59 @@ +// Copyright (c) Microsoft Corporation. All rights reserved. +// Licensed under the MIT License. + +'use strict'; + +// IMPORTANT: This file should only be importing from the '../client/logging' directory, as we +// delete everything in '../client' except for '../client/logging' before running smoke tests. + +import { LogLevel } from '../client/logging/levels'; +import { configureLogger, createLogger, getPreDefinedConfiguration, logToAll } from '../client/logging/logger'; + +const isCI = process.env.TRAVIS === 'true' || process.env.TF_BUILD !== undefined; +const monkeyPatchLogger = createLogger(); + +export function initializeLogger() { + const config = getPreDefinedConfiguration(); + if (isCI && process.env.VSC_PYTHON_LOG_FILE) { + delete config.console; + // This is a separate logger that matches our config but + // does not do any console logging. + configureLogger(monkeyPatchLogger, config); + // Send console.*() to the non-console loggers. + monkeypatchConsole(); + } +} + +/** + * What we're doing here is monkey patching the console.log so we can + * send everything sent to console window into our logs. This is only + * required when we're directly writing to `console.log` or not using + * our `winston logger`. This is something we'd generally turn on only + * on CI so we can see everything logged to the console window + * (via the logs). + */ +function monkeypatchConsole() { + // The logging "streams" (methods) of the node console. + const streams = ['log', 'error', 'warn', 'info', 'debug', 'trace']; + const levels: { [key: string]: LogLevel } = { + error: LogLevel.Error, + warn: LogLevel.Warn + }; + // tslint:disable-next-line:no-any + const consoleAny: any = console; + for (const stream of streams) { + // Using symbols guarantee the properties will be unique & prevents + // clashing with names other code/library may create or have created. + // We could use a closure but it's a bit trickier. + const sym = Symbol.for(stream); + consoleAny[sym] = consoleAny[stream]; + // tslint:disable-next-line: no-function-expression + consoleAny[stream] = function () { + const args = Array.prototype.slice.call(arguments); + const fn = consoleAny[sym]; + fn(...args); + const level = levels[stream] || LogLevel.Info; + logToAll([monkeyPatchLogger], level, args); + }; + } +}