Monkeypatch console.* calls on CI if we are asked to (microsoft#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

@@ -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'

news/3 Code Health/11896.md

@@ -0,0 +1 @@
+Monkeypatch `console.*` calls to the logger only in CI.

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);
-        };
-    }
-}

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';
 
 //======================

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) {

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

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;

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');

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');

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';

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
 

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);
+        };
+    }
+}