Fix random failures on functional tests (#14331)

* Splitting test log

* Fix problem with kernels ports being reused

* Make kernel launcher port round robin only for testing

* Make formatters change only apply during testing

* Add news entry

* Apply black formatting

* Code review feedback and skip flakey remote password test

* Another flakey test

* More CR feedback

* Missed a spot

Author: rchiodo

ThirdPartyNotices-Repository.txt

@@ -20,6 +20,7 @@ Microsoft Python extension for Visual Studio Code incorporates third party mater
 16. ipywidgets (https://github.com/jupyter-widgets)
 17. vscode-cpptools (https://github.com/microsoft/vscode-cpptools)
 18. font-awesome (https://github.com/FortAwesome/Font-Awesome)
+19. mocha (https://github.com/mochajs/mocha)
 
 %%
 Go for Visual Studio Code NOTICES, INFORMATION, AND LICENSE BEGIN HERE
@@ -1195,4 +1196,33 @@ LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM,
 OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE
 SOFTWARE.
 =========================================
-END OF jedi-language-server NOTICES, INFORMATION, AND LICENSE
+END OF jedi-language-server NOTICES, INFORMATION, AND LICENSE
+
+%% mocha NOTICES, INFORMATION, AND LICENSE BEGIN HERE
+=========================================
+
+(The MIT License)
+
+Copyright (c) 2011-2020 OpenJS Foundation and contributors, https://openjsf.org
+
+Permission is hereby granted, free of charge, to any person obtaining
+a copy of this software and associated documentation files (the
+'Software'), to deal in the Software without restriction, including
+without limitation the rights to use, copy, modify, merge, publish,
+distribute, sublicense, and/or sell copies of the Software, and to
+permit persons to whom the Software is furnished to do so, subject to
+the following conditions:
+
+The above copyright notice and this permission notice shall be
+included in all copies or substantial portions of the Software.
+
+THE SOFTWARE IS PROVIDED 'AS IS', WITHOUT WARRANTY OF ANY KIND,
+EXPRESS OR IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF
+MERCHANTABILITY, FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT.
+IN NO EVENT SHALL THE AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY
+CLAIM, DAMAGES OR OTHER LIABILITY, WHETHER IN AN ACTION OF CONTRACT,
+TORT OR OTHERWISE, ARISING FROM, OUT OF OR IN CONNECTION WITH THE
+SOFTWARE OR THE USE OR OTHER DEALINGS IN THE SOFTWARE.
+
+=========================================
+END OF mocha NOTICES, INFORMATION, AND LICENSE

build/.mocha-multi-reporters.config

@@ -1,3 +1,3 @@
 {
-    "reporterEnabled": "spec,mocha-junit-reporter"
+    "reporterEnabled": "./build/ci/scripts/spec_with_pid,mocha-junit-reporter"
 }

build/ci/scripts/spec_with_pid.js

@@ -0,0 +1,96 @@
+'use strict';
+/**
+ * @module Spec
+ */
+/**
+ * Module dependencies.
+ */
+
+var Base = require('mocha/lib/reporters/base');
+var constants = require('mocha/lib/runner').constants;
+var EVENT_RUN_BEGIN = constants.EVENT_RUN_BEGIN;
+var EVENT_RUN_END = constants.EVENT_RUN_END;
+var EVENT_SUITE_BEGIN = constants.EVENT_SUITE_BEGIN;
+var EVENT_SUITE_END = constants.EVENT_SUITE_END;
+var EVENT_TEST_FAIL = constants.EVENT_TEST_FAIL;
+var EVENT_TEST_PASS = constants.EVENT_TEST_PASS;
+var EVENT_TEST_PENDING = constants.EVENT_TEST_PENDING;
+var inherits = require('mocha/lib/utils').inherits;
+var color = Base.color;
+
+/**
+ * Expose `Spec`.
+ */
+
+exports = module.exports = Spec;
+
+/**
+ * Constructs a new `Spec` reporter instance.
+ *
+ * @public
+ * @class
+ * @memberof Mocha.reporters
+ * @extends Mocha.reporters.Base
+ * @param {Runner} runner - Instance triggers reporter actions.
+ * @param {Object} [options] - runner options
+ */
+function Spec(runner, options) {
+    Base.call(this, runner, options);
+
+    var self = this;
+    var indents = 0;
+    var n = 0;
+
+    function indent() {
+        return Array(indents).join('  ');
+    }
+
+    runner.on(EVENT_RUN_BEGIN, function () {
+        Base.consoleLog();
+    });
+
+    runner.on(EVENT_SUITE_BEGIN, function (suite) {
+        ++indents;
+        Base.consoleLog(color('suite', `${process.pid} %s%s`), indent(), suite.title);
+    });
+
+    runner.on(EVENT_SUITE_END, function () {
+        --indents;
+        if (indents === 1) {
+            Base.consoleLog();
+        }
+    });
+
+    runner.on(EVENT_TEST_PENDING, function (test) {
+        var fmt = indent() + color('pending', `${process.pid}   - %s`);
+        Base.consoleLog(fmt, test.title);
+    });
+
+    runner.on(EVENT_TEST_PASS, function (test) {
+        var fmt;
+        if (test.speed === 'fast') {
+            fmt = indent() + color('checkmark', `${process.pid}   ` + Base.symbols.ok) + color('pass', ' %s');
+            Base.consoleLog(fmt, test.title);
+        } else {
+            fmt =
+                indent() +
+                color('checkmark', `${process.pid}   ` + Base.symbols.ok) +
+                color('pass', ' %s') +
+                color(test.speed, ' (%dms)');
+            Base.consoleLog(fmt, test.title, test.duration);
+        }
+    });
+
+    runner.on(EVENT_TEST_FAIL, function (test) {
+        Base.consoleLog(indent() + color('fail', `${process.pid}  %d) %s`), ++n, test.title);
+    });
+
+    runner.once(EVENT_RUN_END, self.epilogue.bind(self));
+}
+
+/**
+ * Inherit from `Base.prototype`.
+ */
+inherits(Spec, Base);
+
+Spec.description = 'hierarchical & verbose [default]';

news/3 Code Health/14290.md

@@ -0,0 +1 @@
+Functional test failures related to kernel ports overlapping.

pythonFiles/vscode_datascience_helpers/tests/logParser.py

@@ -0,0 +1,84 @@
+import sys
+import argparse
+import os
+
+os.system("color")
+from pathlib import Path
+import re
+
+parser = argparse.ArgumentParser(description="Parse a test log into its parts")
+parser.add_argument("testlog", type=str, nargs=1, help="Log to parse")
+parser.add_argument(
+    "--testoutput", action="store_true", help="Show all failures and passes"
+)
+parser.add_argument(
+    "--split",
+    action="store_true",
+    help="Split into per process files. Each file will have the pid appended",
+)
+ansi_escape = re.compile(r"\x1B(?:[@-Z\\-_]|\[[0-?]*[ -/]*[@-~])")
+pid_regex = re.compile(r"(\d+).*")
+
+
+def printTestOutput(testlog):
+    # Find all the lines that don't have a PID in them. These are the test output
+    p = Path(testlog[0])
+    with p.open() as f:
+        for line in f.readlines():
+            stripped = line.strip()
+            if len(stripped) > 2 and stripped[0] == "\x1B" and stripped[1] == "[":
+                print(line.rstrip())  # Should be a test line as it has color encoding
+
+
+def splitByPid(testlog):
+    # Split testlog into prefixed logs based on pid
+    baseFile = os.path.splitext(testlog[0])[0]
+    p = Path(testlog[0])
+    pids = set()
+    logs = {}
+    pid = None
+    with p.open() as f:
+        for line in f.readlines():
+            stripped = ansi_escape.sub("", line.strip())
+            # See if starts with a pid
+            if len(stripped) > 0 and stripped[0] <= "9" and stripped[0] >= "0":
+                # Pull out the pid
+                match = pid_regex.match(stripped)
+
+                # Pids are at least two digits
+                if match != None and len(match.group(1)) > 2:
+                    # Pid is found
+                    pid = int(match.group(1))
+
+                    # See if we've created a log for this pid or not
+                    if not pid in pids:
+                        pids.add(pid)
+                        logFile = "{}_{}.log".format(baseFile, pid)
+                        print("Writing to new log: " + logFile)
+                        logs[pid] = Path(logFile).open(mode="w")
+
+                # Add this line to the log
+                if pid != None:
+                    logs[pid].write(line)
+    # Close all of the open logs
+    for key in logs:
+        logs[key].close()
+
+
+def doWork(args):
+    if not args.testlog:
+        print("Test log should be passed")
+    elif args.testoutput:
+        printTestOutput(args.testlog)
+    elif args.split:
+        splitByPid(args.testlog)
+    else:
+        parser.print_usage()
+
+
+def main():
+    doWork(parser.parse_args())
+
+
+if __name__ == "__main__":
+    main()

src/client/common/process/baseDaemon.ts

@@ -177,14 +177,20 @@ export abstract class BasePythonDaemon {
         return Object.keys(options).every((item) => daemonSupportedSpawnOptions.indexOf(item as any) >= 0);
     }
     protected sendRequestWithoutArgs<R, E, RO>(type: RequestType0<R, E, RO>): Thenable<R> {
-        return Promise.race([this.connection.sendRequest(type), this.connectionClosedDeferred.promise]);
+        if (this.proc && typeof this.proc.exitCode !== 'number') {
+            return Promise.race([this.connection.sendRequest(type), this.connectionClosedDeferred.promise]);
+        }
+        return this.connectionClosedDeferred.promise;
     }
     protected sendRequest<P, R, E, RO>(type: RequestType<P, R, E, RO>, params?: P): Thenable<R> {
-        if (!this.isAlive) {
+        if (!this.isAlive || typeof this.proc.exitCode === 'number') {
             traceError('Daemon is handling a request after death.');
         }
-        // Throw an error if the connection has been closed.
-        return Promise.race([this.connection.sendRequest(type, params), this.connectionClosedDeferred.promise]);
+        if (this.proc && typeof this.proc.exitCode !== 'number') {
+            // Throw an error if the connection has been closed.
+            return Promise.race([this.connection.sendRequest(type, params), this.connectionClosedDeferred.promise]);
+        }
+        return this.connectionClosedDeferred.promise;
     }
     protected throwIfRPCConnectionIsDead() {
         if (!this.isAlive) {

src/client/datascience/kernel-launcher/kernelLauncher.ts

@@ -2,10 +2,15 @@
 // Licensed under the MIT License.
 'use strict';
 
+import * as fsextra from 'fs-extra';
 import { inject, injectable } from 'inversify';
+import * as os from 'os';
+import * as path from 'path';
 import * as portfinder from 'portfinder';
 import { promisify } from 'util';
 import * as uuid from 'uuid/v4';
+import { isTestExecution } from '../../common/constants';
+import { traceInfo } from '../../common/logger';
 import { IProcessServiceFactory } from '../../common/process/types';
 import { Resource } from '../../common/types';
 import { captureTelemetry } from '../../telemetry';
@@ -16,20 +21,62 @@ import { KernelDaemonPool } from './kernelDaemonPool';
 import { KernelProcess } from './kernelProcess';
 import { IKernelConnection, IKernelLauncher, IKernelProcess } from './types';
 
-const PortToStartFrom = 9_000;
+const PortFormatString = `kernelLauncherPortStart_{0}.tmp`;
 
 // Launches and returns a kernel process given a resource or python interpreter.
 // If the given interpreter is undefined, it will try to use the selected interpreter.
 // If the selected interpreter doesn't have a kernel, it will find a kernel on disk and use that.
 @injectable()
 export class KernelLauncher implements IKernelLauncher {
-    private static nextFreePortToTryAndUse = PortToStartFrom;
+    private static startPortPromise = KernelLauncher.computeStartPort();
+    private static nextFreePortToTryAndUsePromise = KernelLauncher.startPortPromise;
     constructor(
         @inject(IProcessServiceFactory) private processExecutionFactory: IProcessServiceFactory,
         @inject(IDataScienceFileSystem) private readonly fs: IDataScienceFileSystem,
         @inject(KernelDaemonPool) private readonly daemonPool: KernelDaemonPool
     ) {}
 
+    // This function is public so it can be called when a test shuts down
+    public static async cleanupStartPort() {
+        try {
+            // Destroy the file
+            const port = await KernelLauncher.startPortPromise;
+            traceInfo(`Cleaning up port start file : ${port}`);
+
+            const filePath = path.join(os.tmpdir(), PortFormatString.format(port.toString()));
+            await fsextra.remove(filePath);
+        } catch (exc) {
+            // If it fails it doesn't really matter. Just a temp file
+            traceInfo(`Kernel port mutex failed to cleanup: `, exc);
+        }
+    }
+
+    private static async computeStartPort(): Promise<number> {
+        if (isTestExecution()) {
+            // Since multiple instances of a test may be running, write our best guess to a shared file
+            let portStart = 9_000;
+            let result = 0;
+            while (result === 0 && portStart < 65_000) {
+                try {
+                    // Try creating a file with the port in the name
+                    const filePath = path.join(os.tmpdir(), PortFormatString.format(portStart.toString()));
+                    await fsextra.open(filePath, 'wx');
+
+                    // If that works, we have our port
+                    result = portStart;
+                } catch {
+                    // If that fails, it should mean the file already exists
+                    portStart += 1_000;
+                }
+            }
+            traceInfo(`Computed port start for KernelLauncher is : ${result}`);
+
+            return result;
+        } else {
+            return 9_000;
+        }
+    }
+
     @captureTelemetry(Telemetry.KernelLauncherPerf)
     public async launch(
         kernelConnectionMetadata: KernelSpecConnectionMetadata | PythonKernelConnectionMetadata,
@@ -49,18 +96,28 @@ export class KernelLauncher implements IKernelLauncher {
         return kernelProcess;
     }
 
-    private async getKernelConnection(): Promise<IKernelConnection> {
+    private async getConnectionPorts(): Promise<number[]> {
         const getPorts = promisify(portfinder.getPorts);
+
+        // Have to wait for static port lookup (it handles case where two VS code instances are running)
+        const nextFreePort = await KernelLauncher.nextFreePortToTryAndUsePromise;
+        const startPort = await KernelLauncher.startPortPromise;
+
         // Ports may have been freed, hence start from begining.
-        const port =
-            KernelLauncher.nextFreePortToTryAndUse > PortToStartFrom + 1_000
-                ? PortToStartFrom
-                : KernelLauncher.nextFreePortToTryAndUse;
+        const port = nextFreePort > startPort + 1_000 ? startPort : nextFreePort;
+
+        // Then get the next set starting at that point
         const ports = await getPorts(5, { host: '127.0.0.1', port });
+
         // We launch restart kernels in the background, its possible other session hasn't started.
         // Ensure we do not use same ports.
-        KernelLauncher.nextFreePortToTryAndUse = Math.max(...ports) + 1;
+        KernelLauncher.nextFreePortToTryAndUsePromise = Promise.resolve(Math.max(...ports) + 1);
 
+        return ports;
+    }
+
+    private async getKernelConnection(): Promise<IKernelConnection> {
+        const ports = await this.getConnectionPorts();
         return {
             version: 1,
             key: uuid(),