Skip to content

Commit 1a6aa56

Browse files
rchiodorchiodo
authored
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
1 parent 4ada810 commit 1a6aa56

20 files changed

Lines changed: 312 additions & 87 deletions

‎ThirdPartyNotices-Repository.txt‎

Lines changed: 31 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -20,6 +20,7 @@ Microsoft Python extension for Visual Studio Code incorporates third party mater
2020
16. ipywidgets (https://github.com/jupyter-widgets)
2121
17. vscode-cpptools (https://github.com/microsoft/vscode-cpptools)
2222
18. font-awesome (https://github.com/FortAwesome/Font-Awesome)
23+
19. mocha (https://github.com/mochajs/mocha)
2324

2425
%%
2526
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,
11951196
OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE
11961197
SOFTWARE.
11971198
=========================================
1198-
END OF jedi-language-server NOTICES, INFORMATION, AND LICENSE
1199+
END OF jedi-language-server NOTICES, INFORMATION, AND LICENSE
1200+
1201+
%% mocha NOTICES, INFORMATION, AND LICENSE BEGIN HERE
1202+
=========================================
1203+
1204+
(The MIT License)
1205+
1206+
Copyright (c) 2011-2020 OpenJS Foundation and contributors, https://openjsf.org
1207+
1208+
Permission is hereby granted, free of charge, to any person obtaining
1209+
a copy of this software and associated documentation files (the
1210+
'Software'), to deal in the Software without restriction, including
1211+
without limitation the rights to use, copy, modify, merge, publish,
1212+
distribute, sublicense, and/or sell copies of the Software, and to
1213+
permit persons to whom the Software is furnished to do so, subject to
1214+
the following conditions:
1215+
1216+
The above copyright notice and this permission notice shall be
1217+
included in all copies or substantial portions of the Software.
1218+
1219+
THE SOFTWARE IS PROVIDED 'AS IS', WITHOUT WARRANTY OF ANY KIND,
1220+
EXPRESS OR IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF
1221+
MERCHANTABILITY, FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT.
1222+
IN NO EVENT SHALL THE AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY
1223+
CLAIM, DAMAGES OR OTHER LIABILITY, WHETHER IN AN ACTION OF CONTRACT,
1224+
TORT OR OTHERWISE, ARISING FROM, OUT OF OR IN CONNECTION WITH THE
1225+
SOFTWARE OR THE USE OR OTHER DEALINGS IN THE SOFTWARE.
1226+
1227+
=========================================
1228+
END OF mocha NOTICES, INFORMATION, AND LICENSE

‎build/.mocha-multi-reporters.config‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -1,3 +1,3 @@
11
{
2-
"reporterEnabled": "spec,mocha-junit-reporter"
2+
"reporterEnabled": "./build/ci/scripts/spec_with_pid,mocha-junit-reporter"
33
}

‎build/ci/scripts/spec_with_pid.js‎

Lines changed: 96 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,96 @@
1+
'use strict';
2+
/**
3+
* @module Spec
4+
*/
5+
/**
6+
* Module dependencies.
7+
*/
8+
9+
var Base = require('mocha/lib/reporters/base');
10+
var constants = require('mocha/lib/runner').constants;
11+
var EVENT_RUN_BEGIN = constants.EVENT_RUN_BEGIN;
12+
var EVENT_RUN_END = constants.EVENT_RUN_END;
13+
var EVENT_SUITE_BEGIN = constants.EVENT_SUITE_BEGIN;
14+
var EVENT_SUITE_END = constants.EVENT_SUITE_END;
15+
var EVENT_TEST_FAIL = constants.EVENT_TEST_FAIL;
16+
var EVENT_TEST_PASS = constants.EVENT_TEST_PASS;
17+
var EVENT_TEST_PENDING = constants.EVENT_TEST_PENDING;
18+
var inherits = require('mocha/lib/utils').inherits;
19+
var color = Base.color;
20+
21+
/**
22+
* Expose `Spec`.
23+
*/
24+
25+
exports = module.exports = Spec;
26+
27+
/**
28+
* Constructs a new `Spec` reporter instance.
29+
*
30+
* @public
31+
* @class
32+
* @memberof Mocha.reporters
33+
* @extends Mocha.reporters.Base
34+
* @param {Runner} runner - Instance triggers reporter actions.
35+
* @param {Object} [options] - runner options
36+
*/
37+
function Spec(runner, options) {
38+
Base.call(this, runner, options);
39+
40+
var self = this;
41+
var indents = 0;
42+
var n = 0;
43+
44+
function indent() {
45+
return Array(indents).join(' ');
46+
}
47+
48+
runner.on(EVENT_RUN_BEGIN, function () {
49+
Base.consoleLog();
50+
});
51+
52+
runner.on(EVENT_SUITE_BEGIN, function (suite) {
53+
++indents;
54+
Base.consoleLog(color('suite', `${process.pid} %s%s`), indent(), suite.title);
55+
});
56+
57+
runner.on(EVENT_SUITE_END, function () {
58+
--indents;
59+
if (indents === 1) {
60+
Base.consoleLog();
61+
}
62+
});
63+
64+
runner.on(EVENT_TEST_PENDING, function (test) {
65+
var fmt = indent() + color('pending', `${process.pid} - %s`);
66+
Base.consoleLog(fmt, test.title);
67+
});
68+
69+
runner.on(EVENT_TEST_PASS, function (test) {
70+
var fmt;
71+
if (test.speed === 'fast') {
72+
fmt = indent() + color('checkmark', `${process.pid} ` + Base.symbols.ok) + color('pass', ' %s');
73+
Base.consoleLog(fmt, test.title);
74+
} else {
75+
fmt =
76+
indent() +
77+
color('checkmark', `${process.pid} ` + Base.symbols.ok) +
78+
color('pass', ' %s') +
79+
color(test.speed, ' (%dms)');
80+
Base.consoleLog(fmt, test.title, test.duration);
81+
}
82+
});
83+
84+
runner.on(EVENT_TEST_FAIL, function (test) {
85+
Base.consoleLog(indent() + color('fail', `${process.pid} %d) %s`), ++n, test.title);
86+
});
87+
88+
runner.once(EVENT_RUN_END, self.epilogue.bind(self));
89+
}
90+
91+
/**
92+
* Inherit from `Base.prototype`.
93+
*/
94+
inherits(Spec, Base);
95+
96+
Spec.description = 'hierarchical & verbose [default]';

‎news/3 Code Health/14290.md‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1 @@
1+
Functional test failures related to kernel ports overlapping.

‎pythonFiles/vscode_datascience_helpers/tests/logParser.py‎

Lines changed: 84 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,84 @@
1+
import sys
2+
import argparse
3+
import os
4+
5+
os.system("color")
6+
from pathlib import Path
7+
import re
8+
9+
parser = argparse.ArgumentParser(description="Parse a test log into its parts")
10+
parser.add_argument("testlog", type=str, nargs=1, help="Log to parse")
11+
parser.add_argument(
12+
"--testoutput", action="store_true", help="Show all failures and passes"
13+
)
14+
parser.add_argument(
15+
"--split",
16+
action="store_true",
17+
help="Split into per process files. Each file will have the pid appended",
18+
)
19+
ansi_escape = re.compile(r"\x1B(?:[@-Z\\-_]|\[[0-?]*[ -/]*[@-~])")
20+
pid_regex = re.compile(r"(\d+).*")
21+
22+
23+
def printTestOutput(testlog):
24+
# Find all the lines that don't have a PID in them. These are the test output
25+
p = Path(testlog[0])
26+
with p.open() as f:
27+
for line in f.readlines():
28+
stripped = line.strip()
29+
if len(stripped) > 2 and stripped[0] == "\x1B" and stripped[1] == "[":
30+
print(line.rstrip()) # Should be a test line as it has color encoding
31+
32+
33+
def splitByPid(testlog):
34+
# Split testlog into prefixed logs based on pid
35+
baseFile = os.path.splitext(testlog[0])[0]
36+
p = Path(testlog[0])
37+
pids = set()
38+
logs = {}
39+
pid = None
40+
with p.open() as f:
41+
for line in f.readlines():
42+
stripped = ansi_escape.sub("", line.strip())
43+
# See if starts with a pid
44+
if len(stripped) > 0 and stripped[0] <= "9" and stripped[0] >= "0":
45+
# Pull out the pid
46+
match = pid_regex.match(stripped)
47+
48+
# Pids are at least two digits
49+
if match != None and len(match.group(1)) > 2:
50+
# Pid is found
51+
pid = int(match.group(1))
52+
53+
# See if we've created a log for this pid or not
54+
if not pid in pids:
55+
pids.add(pid)
56+
logFile = "{}_{}.log".format(baseFile, pid)
57+
print("Writing to new log: " + logFile)
58+
logs[pid] = Path(logFile).open(mode="w")
59+
60+
# Add this line to the log
61+
if pid != None:
62+
logs[pid].write(line)
63+
# Close all of the open logs
64+
for key in logs:
65+
logs[key].close()
66+
67+
68+
def doWork(args):
69+
if not args.testlog:
70+
print("Test log should be passed")
71+
elif args.testoutput:
72+
printTestOutput(args.testlog)
73+
elif args.split:
74+
splitByPid(args.testlog)
75+
else:
76+
parser.print_usage()
77+
78+
79+
def main():
80+
doWork(parser.parse_args())
81+
82+
83+
if __name__ == "__main__":
84+
main()

‎src/client/common/process/baseDaemon.ts‎

Lines changed: 10 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -177,14 +177,20 @@ export abstract class BasePythonDaemon {
177177
return Object.keys(options).every((item) => daemonSupportedSpawnOptions.indexOf(item as any) >= 0);
178178
}
179179
protected sendRequestWithoutArgs<R, E, RO>(type: RequestType0<R, E, RO>): Thenable<R> {
180-
return Promise.race([this.connection.sendRequest(type), this.connectionClosedDeferred.promise]);
180+
if (this.proc && typeof this.proc.exitCode !== 'number') {
181+
return Promise.race([this.connection.sendRequest(type), this.connectionClosedDeferred.promise]);
182+
}
183+
return this.connectionClosedDeferred.promise;
181184
}
182185
protected sendRequest<P, R, E, RO>(type: RequestType<P, R, E, RO>, params?: P): Thenable<R> {
183-
if (!this.isAlive) {
186+
if (!this.isAlive || typeof this.proc.exitCode === 'number') {
184187
traceError('Daemon is handling a request after death.');
185188
}
186-
// Throw an error if the connection has been closed.
187-
return Promise.race([this.connection.sendRequest(type, params), this.connectionClosedDeferred.promise]);
189+
if (this.proc && typeof this.proc.exitCode !== 'number') {
190+
// Throw an error if the connection has been closed.
191+
return Promise.race([this.connection.sendRequest(type, params), this.connectionClosedDeferred.promise]);
192+
}
193+
return this.connectionClosedDeferred.promise;
188194
}
189195
protected throwIfRPCConnectionIsDead() {
190196
if (!this.isAlive) {

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

Lines changed: 65 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -2,10 +2,15 @@
22
// Licensed under the MIT License.
33
'use strict';
44

5+
import * as fsextra from 'fs-extra';
56
import { inject, injectable } from 'inversify';
7+
import * as os from 'os';
8+
import * as path from 'path';
69
import * as portfinder from 'portfinder';
710
import { promisify } from 'util';
811
import * as uuid from 'uuid/v4';
12+
import { isTestExecution } from '../../common/constants';
13+
import { traceInfo } from '../../common/logger';
914
import { IProcessServiceFactory } from '../../common/process/types';
1015
import { Resource } from '../../common/types';
1116
import { captureTelemetry } from '../../telemetry';
@@ -16,20 +21,62 @@ import { KernelDaemonPool } from './kernelDaemonPool';
1621
import { KernelProcess } from './kernelProcess';
1722
import { IKernelConnection, IKernelLauncher, IKernelProcess } from './types';
1823

19-
const PortToStartFrom = 9_000;
24+
const PortFormatString = `kernelLauncherPortStart_{0}.tmp`;
2025

2126
// Launches and returns a kernel process given a resource or python interpreter.
2227
// If the given interpreter is undefined, it will try to use the selected interpreter.
2328
// If the selected interpreter doesn't have a kernel, it will find a kernel on disk and use that.
2429
@injectable()
2530
export class KernelLauncher implements IKernelLauncher {
26-
private static nextFreePortToTryAndUse = PortToStartFrom;
31+
private static startPortPromise = KernelLauncher.computeStartPort();
32+
private static nextFreePortToTryAndUsePromise = KernelLauncher.startPortPromise;
2733
constructor(
2834
@inject(IProcessServiceFactory) private processExecutionFactory: IProcessServiceFactory,
2935
@inject(IDataScienceFileSystem) private readonly fs: IDataScienceFileSystem,
3036
@inject(KernelDaemonPool) private readonly daemonPool: KernelDaemonPool
3137
) {}
3238

39+
// This function is public so it can be called when a test shuts down
40+
public static async cleanupStartPort() {
41+
try {
42+
// Destroy the file
43+
const port = await KernelLauncher.startPortPromise;
44+
traceInfo(`Cleaning up port start file : ${port}`);
45+
46+
const filePath = path.join(os.tmpdir(), PortFormatString.format(port.toString()));
47+
await fsextra.remove(filePath);
48+
} catch (exc) {
49+
// If it fails it doesn't really matter. Just a temp file
50+
traceInfo(`Kernel port mutex failed to cleanup: `, exc);
51+
}
52+
}
53+
54+
private static async computeStartPort(): Promise<number> {
55+
if (isTestExecution()) {
56+
// Since multiple instances of a test may be running, write our best guess to a shared file
57+
let portStart = 9_000;
58+
let result = 0;
59+
while (result === 0 && portStart < 65_000) {
60+
try {
61+
// Try creating a file with the port in the name
62+
const filePath = path.join(os.tmpdir(), PortFormatString.format(portStart.toString()));
63+
await fsextra.open(filePath, 'wx');
64+
65+
// If that works, we have our port
66+
result = portStart;
67+
} catch {
68+
// If that fails, it should mean the file already exists
69+
portStart += 1_000;
70+
}
71+
}
72+
traceInfo(`Computed port start for KernelLauncher is : ${result}`);
73+
74+
return result;
75+
} else {
76+
return 9_000;
77+
}
78+
}
79+
3380
@captureTelemetry(Telemetry.KernelLauncherPerf)
3481
public async launch(
3582
kernelConnectionMetadata: KernelSpecConnectionMetadata | PythonKernelConnectionMetadata,
@@ -49,18 +96,28 @@ export class KernelLauncher implements IKernelLauncher {
4996
return kernelProcess;
5097
}
5198

52-
private async getKernelConnection(): Promise<IKernelConnection> {
99+
private async getConnectionPorts(): Promise<number[]> {
53100
const getPorts = promisify(portfinder.getPorts);
101+
102+
// Have to wait for static port lookup (it handles case where two VS code instances are running)
103+
const nextFreePort = await KernelLauncher.nextFreePortToTryAndUsePromise;
104+
const startPort = await KernelLauncher.startPortPromise;
105+
54106
// Ports may have been freed, hence start from begining.
55-
const port =
56-
KernelLauncher.nextFreePortToTryAndUse > PortToStartFrom + 1_000
57-
? PortToStartFrom
58-
: KernelLauncher.nextFreePortToTryAndUse;
107+
const port = nextFreePort > startPort + 1_000 ? startPort : nextFreePort;
108+
109+
// Then get the next set starting at that point
59110
const ports = await getPorts(5, { host: '127.0.0.1', port });
111+
60112
// We launch restart kernels in the background, its possible other session hasn't started.
61113
// Ensure we do not use same ports.
62-
KernelLauncher.nextFreePortToTryAndUse = Math.max(...ports) + 1;
114+
KernelLauncher.nextFreePortToTryAndUsePromise = Promise.resolve(Math.max(...ports) + 1);
63115

116+
return ports;
117+
}
118+
119+
private async getKernelConnection(): Promise<IKernelConnection> {
120+
const ports = await this.getConnectionPorts();
64121
return {
65122
version: 1,
66123
key: uuid(),

0 commit comments

Comments
 (0)