Logging cleanup.

src/client/common/logger.ts

@@ -1,10 +1,10 @@
+// These are all just temporary aliases, for backward compatibility
+// and to avoid churn.
 export {
-    // aliases:
-    // (temporarily for backward compatibility and to avoid churn)
     traceDecorators,
-    traceError,
-    traceInfo,
-    traceVerbose,
-    traceWarning
-} from '../logging/_trace';
-export { TraceOptions as LogOptions } from '../logging/types';
+    logError as traceError,
+    logInfo as traceInfo,
+    logVerbose as traceVerbose,
+    logWarning as traceWarning
+} from '../logging';
+export { TraceOptions as LogOptions } from '../logging/trace';

src/client/common/utils/async.ts

@@ -27,6 +27,16 @@ export async function waitForPromise<T>(promise: Promise<T>, timeout: number): P
     });
 }
 
+// tslint:disable-next-line: no-any
+export function isThenable<T>(v: any): v is Thenable<T> {
+    return typeof v?.then === 'function';
+}
+
+// tslint:disable-next-line: no-any
+export function isPromise<T>(v: any): v is Promise<T> {
+    return typeof v?.then === 'function' && typeof v?.catch === 'function';
+}
+
 //======================
 // Deferred
 

src/client/common/utils/decorators.ts

@@ -8,6 +8,7 @@ import { traceError, traceVerbose } from '../logger';
 import { Resource } from '../types';
 import { createDeferred, Deferred } from './async';
 import { getCacheKeyFromFunctionArgs, getGlobalCacheStore, InMemoryInterpreterSpecificCache } from './cacheUtils';
+import { TraceInfo, tracing } from './misc';
 
 // tslint:disable-next-line:no-require-imports no-var-requires
 const _debounce = require('lodash/debounce') as typeof import('lodash/debounce');
@@ -225,3 +226,37 @@ export function displayProgress(title: string, location = ProgressLocation.Windo
         };
     };
 }
+
+// Information about a function/method call.
+export type CallInfo = {
+    kind: string; // "Class", etc.
+    name: string;
+    // tslint:disable-next-line:no-any
+    args: any[];
+};
+
+// Return a decorator that traces the decorated function.
+export function trace(log: (c: CallInfo, t: TraceInfo) => void) {
+    // tslint:disable-next-line:no-function-expression no-any
+    return function (_: Object, __: string, descriptor: TypedPropertyDescriptor<any>) {
+        const originalMethod = descriptor.value;
+        // tslint:disable-next-line:no-function-expression no-any
+        descriptor.value = function (...args: any[]) {
+            const call = {
+                kind: 'Class',
+                name: _ && _.constructor ? _.constructor.name : '',
+                args
+            };
+            // tslint:disable-next-line:no-this-assignment no-invalid-this
+            const scope = this;
+            return tracing(
+                // "log()"
+                (t) => log(call, t),
+                // "run()"
+                () => originalMethod.apply(scope, args)
+            );
+        };
+
+        return descriptor;
+    };
+}

src/client/common/utils/misc.ts

@@ -4,6 +4,8 @@
 import { Uri } from 'vscode';
 import { InterpreterUri } from '../installer/types';
 import { IAsyncDisposable, IDisposable, Resource } from '../types';
+import { isPromise } from './async';
+import { StopWatch } from './stopWatch';
 
 // tslint:disable-next-line:no-empty
 export function noop() {}
@@ -38,6 +40,46 @@ export async function usingAsync<T extends IAsyncDisposable, R>(
     }
 }
 
+// Information about a traced function/method call.
+export type TraceInfo = {
+    elapsed: number; // milliseconds
+    // Either returnValue or err will be set.
+    // tslint:disable-next-line:no-any
+    returnValue?: any;
+    err?: Error;
+};
+
+// Call run(), call log() with the trace info, and return the result.
+export function tracing<T>(log: (t: TraceInfo) => void, run: () => T): T {
+    const timer = new StopWatch();
+    try {
+        // tslint:disable-next-line:no-invalid-this no-use-before-declare no-unsafe-any
+        const result = run();
+
+        // If method being wrapped returns a promise then wait for it.
+        if (isPromise(result)) {
+            // tslint:disable-next-line:prefer-type-cast
+            (result as Promise<void>)
+                .then((data) => {
+                    log({ elapsed: timer.elapsedTime, returnValue: data });
+                    return data;
+                })
+                .catch((ex) => {
+                    log({ elapsed: timer.elapsedTime, err: ex });
+                    // tslint:disable-next-line:no-suspicious-comment
+                    // TODO(GH-11645) Re-throw the error like we do
+                    // in the non-Promise case.
+                });
+        } else {
+            log({ elapsed: timer.elapsedTime, returnValue: result });
+        }
+        return result;
+    } catch (ex) {
+        log({ elapsed: timer.elapsedTime, err: ex });
+        throw ex;
+    }
+}
+
 /**
  * Checking whether something is a Resource (Uri/undefined).
  * Using `instanceof Uri` doesn't always work as the object is not an instance of Uri (at least not in tests).

src/client/logging/_global.ts

@@ -0,0 +1,157 @@
+// Copyright (c) Microsoft Corporation. All rights reserved.
+// Licensed under the MIT License.
+'use strict';
+
+import { isCI, isTestExecution } from '../common/constants';
+import { CallInfo } from '../common/utils/decorators';
+import { LogLevel } from './levels';
+import { configureLogger, createLogger, ILogger, LoggerConfig, logToAll } from './logger';
+import { createTracingDecorator, LogInfo, TraceOptions, tracing as _tracing } from './trace';
+import { Arguments } from './util';
+
+const globalLogger = createLogger();
+initialize();
+
+/**
+ * Initialize the logger.
+ *
+ * For console we do two things here:
+ * - Anything written to the logger will be displayed in the console
+ *   window as well  This is the behavior of the extension when running
+ *   it.  When running tests on CI, we might not want this behavior, as
+ *   it'll pollute the test output with logging (as mentioned this is
+ *   optional).  Messages logged using our logger will be prefixed with
+ *   `Python Extension: ....` for console window.  This way, its easy
+ *   to identify messages specific to the python extension.
+ * - Monkey patch the console.log and similar methods to send messages
+ *   to the file logger.  When running UI tests or similar, and we want
+ *   to see everything that was dumped into `console window`, then we
+ *   need to hijack the console logger.  To do this we need to monkey
+ *   patch the console methods.  This is optional (generally done when
+ *   running tests on CI).
+ *
+ * For the logfile:
+ * - we send all logging output to a log file.  We log to the file
+ *   only if a file has been specified as an env variable.  Currently
+ *   this is setup on CI servers.
+ */
+function initialize() {
+    const config: LoggerConfig = {};
+    let nonConsole = false;
+
+    // Do not log to console if running tests and we're not
+    // asked to do so.
+    if (!isTestExecution() || process.env.VSC_PYTHON_FORCE_LOGGING) {
+        config.console = {};
+        // In CI there's no need for the label.
+        if (!isCI) {
+            config.console.label = 'Python Extension:';
+        }
+    }
+    if (process.env.VSC_PYTHON_LOG_FILE) {
+        config.file = {
+            logfile: process.env.VSC_PYTHON_LOG_FILE
+        };
+        nonConsole = true;
+    }
+    configureLogger(globalLogger, config);
+
+    if (isCI && nonConsole) {
+        delete config.console;
+        // Send console.*() to the non-console loggers.
+        monkeypatchConsole(
+            // This is a separate logger that matches our config but
+            // does not do any console logging.
+            createLogger(config)
+        );
+    }
+}
+
+// Emit a log message derived from the args to all enabled transports.
+export function log(logLevel: LogLevel, ...args: Arguments) {
+    logToAll([globalLogger], logLevel, args);
+}
+
+// tslint:disable-next-line:no-any
+export function logVerbose(...args: any[]) {
+    log(LogLevel.Info, ...args);
+}
+
+// tslint:disable-next-line:no-any
+export function logError(...args: any[]) {
+    log(LogLevel.Error, ...args);
+}
+
+// tslint:disable-next-line:no-any
+export function logInfo(...args: any[]) {
+    log(LogLevel.Info, ...args);
+}
+
+// tslint:disable-next-line:no-any
+export function logWarning(...args: any[]) {
+    log(LogLevel.Warn, ...args);
+}
+
+// This is like a "context manager" that logs tracing info.
+export function tracing<T>(info: LogInfo, run: () => T, call?: CallInfo): T {
+    return _tracing([globalLogger], info, run, call);
+}
+
+export namespace traceDecorators {
+    const DEFAULT_OPTS: TraceOptions = TraceOptions.Arguments | TraceOptions.ReturnValue;
+
+    export function verbose(message: string, opts: TraceOptions = DEFAULT_OPTS) {
+        return createTracingDecorator([globalLogger], { message, opts });
+    }
+    export function error(message: string) {
+        const opts = DEFAULT_OPTS;
+        const level = LogLevel.Error;
+        return createTracingDecorator([globalLogger], { message, opts, level });
+    }
+    export function info(message: string) {
+        const opts = TraceOptions.None;
+        return createTracingDecorator([globalLogger], { message, opts });
+    }
+    export function warn(message: string) {
+        const opts = DEFAULT_OPTS;
+        const level = LogLevel.Warn;
+        return createTracingDecorator([globalLogger], { message, opts, level });
+    }
+}
+
+// Ensure that the console functions are bound before monkeypatching.
+import './transports';
+
+/**
+ * What we're doing here is monkey patching the console.log so we can
+ * send everything sent to console window into our logs.  This is only
+ * required when we're directly writing to `console.log` or not using
+ * our `winston logger`.  This is something we'd generally turn on, only
+ * on CI so we can see everything logged to the console window
+ * (via the logs).
+ */
+function monkeypatchConsole(logger: ILogger) {
+    // The logging "streams" (methods) of the node console.
+    const streams = ['log', 'error', 'warn', 'info', 'debug', 'trace'];
+    const levels: { [key: string]: LogLevel } = {
+        error: LogLevel.Error,
+        warn: LogLevel.Warn
+    };
+    // tslint:disable-next-line:no-any
+    const consoleAny: any = console;
+    for (const stream of streams) {
+        // Using symbols guarantee the properties will be unique & prevents
+        // clashing with names other code/library may create or have created.
+        // We could use a closure but it's a bit trickier.
+        const sym = Symbol.for(stream);
+        consoleAny[sym] = consoleAny[stream];
+        // tslint:disable-next-line: no-function-expression
+        consoleAny[stream] = function () {
+            const args = Array.prototype.slice.call(arguments);
+            const fn = consoleAny[sym];
+            fn(...args);
+            const level = levels[stream] || LogLevel.Info;
+            logToAll([logger], level, args);
+        };
+    }
+}