From 998a0a54a8107b2033a25df36569d090a64244d4 Mon Sep 17 00:00:00 2001 From: Eleanor Boyd Date: Mon, 25 Sep 2023 15:01:50 -0700 Subject: [PATCH] Add await for stdout (#22049) Add await so all output is read before ending the run instance. --- .../testing/testController/common/server.ts | 29 ++++++++-- .../testing/testController/common/utils.ts | 2 +- .../testing/testController/controller.ts | 1 - .../pytest/pytestDiscoveryAdapter.ts | 21 ++++--- .../pytest/pytestExecutionAdapter.ts | 55 +++++++++++++------ src/test/mocks/mockChildProcess.ts | 6 +- .../testing/common/testingPayloadsEot.test.ts | 11 ++-- .../pytestExecutionAdapter.unit.test.ts | 2 +- .../testCancellationRunAdapters.unit.test.ts | 53 ++++++++++++++---- 9 files changed, 126 insertions(+), 54 deletions(-) diff --git a/src/client/testing/testController/common/server.ts b/src/client/testing/testController/common/server.ts index 699f7f754122..d47587386069 100644 --- a/src/client/testing/testController/common/server.ts +++ b/src/client/testing/testController/common/server.ts @@ -5,6 +5,7 @@ import * as net from 'net'; import * as crypto from 'crypto'; import { Disposable, Event, EventEmitter, TestRun } from 'vscode'; import * as path from 'path'; +import { ChildProcess } from 'child_process'; import { ExecutionFactoryCreateWithEnvironmentOptions, ExecutionResult, @@ -86,7 +87,7 @@ export class PythonTestServer implements ITestServer, Disposable { // what payload is so small it doesn't include the whole UUID think got this if (extractedJsonPayload.uuid !== undefined && extractedJsonPayload.cleanedJsonData !== undefined) { // if a full json was found in the buffer, fire the data received event then keep cycling with the remaining raw data. - traceInfo(`Firing data received event, ${extractedJsonPayload.cleanedJsonData}`); + traceLog(`Firing data received event, ${extractedJsonPayload.cleanedJsonData}`); this._fireDataReceived(extractedJsonPayload.uuid, extractedJsonPayload.cleanedJsonData); } buffer = Buffer.from(extractedJsonPayload.remainingRawData); @@ -223,13 +224,23 @@ export class PythonTestServer implements ITestServer, Disposable { // This means it is running discovery traceLog(`Discovering unittest tests with arguments: ${args}\r\n`); } - const deferred = createDeferred>(); - const result = execService.execObservable(args, spawnOptions); + const deferredTillExecClose = createDeferred>(); + + let resultProc: ChildProcess | undefined; + runInstance?.token.onCancellationRequested(() => { traceInfo('Test run cancelled, killing unittest subprocess.'); - result?.proc?.kill(); + // if the resultProc exists just call kill on it which will handle resolving the ExecClose deferred, otherwise resolve the deferred here. + if (resultProc) { + resultProc?.kill(); + } else { + deferredTillExecClose?.resolve(); + } }); + const result = execService?.execObservable(args, spawnOptions); + resultProc = result?.proc; + // Take all output from the subprocess and add it to the test output channel. This will be the pytest output. // Displays output to user and ensure the subprocess doesn't run into buffer overflow. result?.proc?.stdout?.on('data', (data) => { @@ -238,6 +249,12 @@ export class PythonTestServer implements ITestServer, Disposable { result?.proc?.stderr?.on('data', (data) => { spawnOptions?.outputChannel?.append(data.toString()); }); + result?.proc?.on('exit', (code, signal) => { + if (code !== 0) { + traceError(`Subprocess exited unsuccessfully with exit code ${code} and signal ${signal}`); + } + }); + result?.proc?.on('exit', (code, signal) => { // if the child has testIds then this is a run request if (code !== 0 && testIds && testIds?.length !== 0) { @@ -269,9 +286,9 @@ export class PythonTestServer implements ITestServer, Disposable { data: JSON.stringify(createEOTPayload(true)), }); } - deferred.resolve({ stdout: '', stderr: '' }); + deferredTillExecClose.resolve({ stdout: '', stderr: '' }); }); - await deferred.promise; + await deferredTillExecClose.promise; } } catch (ex) { traceError(`Error while server attempting to run unittest command: ${ex}`); diff --git a/src/client/testing/testController/common/utils.ts b/src/client/testing/testController/common/utils.ts index dc254a9900a1..1272ff37fb5d 100644 --- a/src/client/testing/testController/common/utils.ts +++ b/src/client/testing/testController/common/utils.ts @@ -43,7 +43,7 @@ export const JSONRPC_UUID_HEADER = 'Request-uuid'; export const JSONRPC_CONTENT_LENGTH_HEADER = 'Content-Length'; export const JSONRPC_CONTENT_TYPE_HEADER = 'Content-Type'; -export function createEOTDeferred(): Deferred { +export function createTestingDeferred(): Deferred { return createDeferred(); } diff --git a/src/client/testing/testController/controller.ts b/src/client/testing/testController/controller.ts index 0c7db5594004..af77ab2b2525 100644 --- a/src/client/testing/testController/controller.ts +++ b/src/client/testing/testController/controller.ts @@ -462,7 +462,6 @@ export class PythonTestController implements ITestController, IExtensionSingleAc ); } } - if (!settings.testing.pytestEnabled && !settings.testing.unittestEnabled) { unconfiguredWorkspaces.push(workspace); } diff --git a/src/client/testing/testController/pytest/pytestDiscoveryAdapter.ts b/src/client/testing/testController/pytest/pytestDiscoveryAdapter.ts index c03baeae0421..c0e1a310ee4a 100644 --- a/src/client/testing/testController/pytest/pytestDiscoveryAdapter.ts +++ b/src/client/testing/testController/pytest/pytestDiscoveryAdapter.ts @@ -4,7 +4,6 @@ import * as path from 'path'; import { Uri } from 'vscode'; import { ExecutionFactoryCreateWithEnvironmentOptions, - ExecutionResult, IPythonExecutionFactory, SpawnOptions, } from '../../../common/process/types'; @@ -19,7 +18,7 @@ import { ITestResultResolver, ITestServer, } from '../common/types'; -import { createDiscoveryErrorPayload, createEOTPayload } from '../common/utils'; +import { createDiscoveryErrorPayload, createEOTPayload, createTestingDeferred } from '../common/utils'; /** * Wrapper class for unittest test discovery. This is where we call `runTestCommand`. #this seems incorrectly copied @@ -47,6 +46,7 @@ export class PytestTestDiscoveryAdapter implements ITestDiscoveryAdapter { await this.runPytestDiscovery(uri, uuid, executionFactory); } finally { await deferredTillEOT.promise; + traceVerbose('deferredTill EOT resolved'); disposeDataReceiver(this.testServer); } // this is only a placeholder to handle function overloading until rewrite is finished @@ -55,7 +55,6 @@ export class PytestTestDiscoveryAdapter implements ITestDiscoveryAdapter { } async runPytestDiscovery(uri: Uri, uuid: string, executionFactory?: IPythonExecutionFactory): Promise { - const deferred = createDeferred(); const relativePathToPytest = 'pythonFiles'; const fullPluginPath = path.join(EXTENSION_ROOT_DIR, relativePathToPytest); const settings = this.configSettings.getSettings(uri); @@ -83,9 +82,10 @@ export class PytestTestDiscoveryAdapter implements ITestDiscoveryAdapter { }; const execService = await executionFactory?.createActivatedEnvironment(creationOptions); // delete UUID following entire discovery finishing. - const deferredExec = createDeferred>(); const execArgs = ['-m', 'pytest', '-p', 'vscode_pytest', '--collect-only'].concat(pytestArgs); traceVerbose(`Running pytest discovery with command: ${execArgs.join(' ')}`); + + const deferredTillExecClose: Deferred = createTestingDeferred(); const result = execService?.execObservable(execArgs, spawnOptions); // Take all output from the subprocess and add it to the test output channel. This will be the pytest output. @@ -97,6 +97,11 @@ export class PytestTestDiscoveryAdapter implements ITestDiscoveryAdapter { spawnOptions.outputChannel?.append(data.toString()); }); result?.proc?.on('exit', (code, signal) => { + if (code !== 0) { + traceError(`Subprocess exited unsuccessfully with exit code ${code} and signal ${signal}.`); + } + }); + result?.proc?.on('close', (code, signal) => { if (code !== 0) { traceError( `Subprocess exited unsuccessfully with exit code ${code} and signal ${signal}. Creating and sending error discovery payload`, @@ -112,10 +117,10 @@ export class PytestTestDiscoveryAdapter implements ITestDiscoveryAdapter { data: JSON.stringify(createEOTPayload(true)), }); } - deferredExec.resolve({ stdout: '', stderr: '' }); - deferred.resolve(); + // deferredTillEOT is resolved when all data sent on stdout and stderr is received, close event is only called when this occurs + // due to the sync reading of the output. + deferredTillExecClose?.resolve(); }); - - await deferredExec.promise; + await deferredTillExecClose.promise; } } diff --git a/src/client/testing/testController/pytest/pytestExecutionAdapter.ts b/src/client/testing/testController/pytest/pytestExecutionAdapter.ts index 085af40375d4..8020be17cf90 100644 --- a/src/client/testing/testController/pytest/pytestExecutionAdapter.ts +++ b/src/client/testing/testController/pytest/pytestExecutionAdapter.ts @@ -3,9 +3,10 @@ import { TestRun, Uri } from 'vscode'; import * as path from 'path'; +import { ChildProcess } from 'child_process'; import { IConfigurationService, ITestOutputChannel } from '../../../common/types'; -import { Deferred, createDeferred } from '../../../common/utils/async'; -import { traceError, traceInfo } from '../../../logging'; +import { Deferred } from '../../../common/utils/async'; +import { traceError, traceInfo, traceVerbose } from '../../../logging'; import { DataReceivedEvent, ExecutionTestPayload, @@ -15,7 +16,6 @@ import { } from '../common/types'; import { ExecutionFactoryCreateWithEnvironmentOptions, - ExecutionResult, IPythonExecutionFactory, SpawnOptions, } from '../../../common/process/types'; @@ -42,7 +42,9 @@ export class PytestTestExecutionAdapter implements ITestExecutionAdapter { debugLauncher?: ITestDebugLauncher, ): Promise { const uuid = this.testServer.createUUID(uri.fsPath); - const deferredTillEOT: Deferred = utils.createEOTDeferred(); + // deferredTillEOT is resolved when all data sent over payload is received + const deferredTillEOT: Deferred = utils.createTestingDeferred(); + const dataReceivedDisposable = this.testServer.onRunDataReceived((e: DataReceivedEvent) => { if (runInstance) { const eParsed = JSON.parse(e.data); @@ -60,8 +62,9 @@ export class PytestTestExecutionAdapter implements ITestExecutionAdapter { traceInfo("Test run cancelled, resolving 'till EOT' deferred."); deferredTillEOT.resolve(); }); + try { - this.runTestsNew( + await this.runTestsNew( uri, testIds, uuid, @@ -73,6 +76,7 @@ export class PytestTestExecutionAdapter implements ITestExecutionAdapter { ); } finally { await deferredTillEOT.promise; + traceVerbose('deferredTill EOT resolved'); disposeDataReceiver(this.testServer); } @@ -123,7 +127,6 @@ export class PytestTestExecutionAdapter implements ITestExecutionAdapter { }; // need to check what will happen in the exec service is NOT defined and is null const execService = await executionFactory?.createActivatedEnvironment(creationOptions); - try { // Remove positional test folders and files, we will add as needed per node const testArgs = removePositionalFoldersAndFiles(pytestArgs); @@ -159,19 +162,28 @@ export class PytestTestExecutionAdapter implements ITestExecutionAdapter { deferredTillEOT?.resolve(); }); } else { + // deferredTillExecClose is resolved when all stdout and stderr is read + const deferredTillExecClose: Deferred = utils.createTestingDeferred(); // combine path to run script with run args const scriptPath = path.join(fullPluginPath, 'vscode_pytest', 'run_pytest_script.py'); const runArgs = [scriptPath, ...testArgs]; traceInfo(`Running pytest with arguments: ${runArgs.join(' ')}\r\n`); - const deferredExec = createDeferred>(); - const result = execService?.execObservable(runArgs, spawnOptions); + let resultProc: ChildProcess | undefined; runInstance?.token.onCancellationRequested(() => { traceInfo('Test run cancelled, killing pytest subprocess.'); - result?.proc?.kill(); + // if the resultProc exists just call kill on it which will handle resolving the ExecClose deferred, otherwise resolve the deferred here. + if (resultProc) { + resultProc?.kill(); + } else { + deferredTillExecClose?.resolve(); + } }); + const result = execService?.execObservable(runArgs, spawnOptions); + resultProc = result?.proc; + // Take all output from the subprocess and add it to the test output channel. This will be the pytest output. // Displays output to user and ensure the subprocess doesn't run into buffer overflow. result?.proc?.stdout?.on('data', (data) => { @@ -180,15 +192,20 @@ export class PytestTestExecutionAdapter implements ITestExecutionAdapter { result?.proc?.stderr?.on('data', (data) => { this.outputChannel?.append(data.toString()); }); - result?.proc?.on('exit', (code, signal) => { - traceInfo('Test run finished, subprocess exited.'); + if (code !== 0 && testIds) { + traceError(`Subprocess exited unsuccessfully with exit code ${code} and signal ${signal}.`); + } + }); + + result?.proc?.on('close', (code, signal) => { + traceVerbose('Test run finished, subprocess closed.'); // if the child has testIds then this is a run request + // if the child process exited with a non-zero exit code, then we need to send the error payload. if (code !== 0 && testIds) { traceError( - `Subprocess exited unsuccessfully with exit code ${code} and signal ${signal}. Creating and sending error execution payload`, + `Subprocess closed unsuccessfully with exit code ${code} and signal ${signal}. Creating and sending error execution payload`, ); - // if the child process exited with a non-zero exit code, then we need to send the error payload. this.testServer.triggerRunDataReceivedEvent({ uuid, data: JSON.stringify(utils.createExecutionErrorPayload(code, signal, testIds, cwd)), @@ -199,16 +216,22 @@ export class PytestTestExecutionAdapter implements ITestExecutionAdapter { data: JSON.stringify(utils.createEOTPayload(true)), }); } - deferredExec.resolve({ stdout: '', stderr: '' }); + // deferredTillEOT is resolved when all data sent on stdout and stderr is received, close event is only called when this occurs + // due to the sync reading of the output. + deferredTillExecClose?.resolve(); }); - await deferredExec.promise; + await deferredTillExecClose?.promise; } } catch (ex) { traceError(`Error while running tests: ${testIds}\r\n${ex}\r\n\r\n`); return Promise.reject(ex); } - const executionPayload: ExecutionTestPayload = { cwd, status: 'success', error: '' }; + const executionPayload: ExecutionTestPayload = { + cwd, + status: 'success', + error: '', + }; return executionPayload; } } diff --git a/src/test/mocks/mockChildProcess.ts b/src/test/mocks/mockChildProcess.ts index a46d66d79ca0..c0a24b1c955f 100644 --- a/src/test/mocks/mockChildProcess.ts +++ b/src/test/mocks/mockChildProcess.ts @@ -133,9 +133,9 @@ export class MockChildProcess extends EventEmitter { emit(event: string | symbol, ...args: unknown[]): boolean { if (this.eventMap.has(event.toString())) { - this.eventMap.get(event.toString()).forEach((listener: (arg0: unknown) => void) => { - const argsArray = Array.isArray(args) ? args : [args]; - listener(argsArray); + this.eventMap.get(event.toString()).forEach((listener: (...arg0: unknown[]) => void) => { + const argsArray: unknown[] = Array.isArray(args) ? args : [args]; + listener(...argsArray); }); } return true; diff --git a/src/test/testing/common/testingPayloadsEot.test.ts b/src/test/testing/common/testingPayloadsEot.test.ts index 227ad5fa1697..9025248c66ff 100644 --- a/src/test/testing/common/testingPayloadsEot.test.ts +++ b/src/test/testing/common/testingPayloadsEot.test.ts @@ -66,6 +66,7 @@ suite('EOT tests', () => { let testController: TestController; let stubExecutionFactory: typeMoq.IMock; let client: net.Socket; + let mockProc: MockChildProcess; const sandbox = sinon.createSandbox(); // const unittestProvider: TestProvider = UNITTEST_PROVIDER; // const pytestProvider: TestProvider = PYTEST_PROVIDER; @@ -86,7 +87,7 @@ suite('EOT tests', () => { traceLog('Socket connection error:', error); }); - const mockProc = new MockChildProcess('', ['']); + mockProc = new MockChildProcess('', ['']); const output2 = new Observable>(() => { /* no op */ }); @@ -156,15 +157,17 @@ suite('EOT tests', () => { } })(client, payloadArray[i]); } + mockProc.emit('close', 0, null); client.end(); }); resultResolver = new PythonResultResolver(testController, PYTEST_PROVIDER, workspaceUri); resultResolver._resolveExecution = async (payload, _token?) => { // the payloads that get to the _resolveExecution are all data and should be successful. + actualCollectedResult = actualCollectedResult + JSON.stringify(payload.result); assert.strictEqual(payload.status, 'success', "Expected status to be 'success'"); assert.ok(payload.result, 'Expected results to be present'); - actualCollectedResult = actualCollectedResult + JSON.stringify(payload.result); + return Promise.resolve(); }; // set workspace to test workspace folder @@ -200,10 +203,6 @@ suite('EOT tests', () => { actualCollectedResult, "Expected collected result to match 'data'", ); - // nervous about this not testing race conditions correctly - // client.end(); - // verify that the _resolveExecution was called once per test - // assert.strictEqual(callCount, 1, 'Expected _resolveExecution to be called once'); }); }); }); diff --git a/src/test/testing/testController/pytest/pytestExecutionAdapter.unit.test.ts b/src/test/testing/testController/pytest/pytestExecutionAdapter.unit.test.ts index 9cc428ab0a4c..a2e5c810dc86 100644 --- a/src/test/testing/testController/pytest/pytestExecutionAdapter.unit.test.ts +++ b/src/test/testing/testController/pytest/pytestExecutionAdapter.unit.test.ts @@ -268,7 +268,7 @@ suite('pytest test execution adapter', () => { traceInfo('stubs launch debugger'); deferredEOT.resolve(); }); - const utilsCreateEOTStub: sinon.SinonStub = sinon.stub(util, 'createEOTDeferred'); + const utilsCreateEOTStub: sinon.SinonStub = sinon.stub(util, 'createTestingDeferred'); utilsCreateEOTStub.callsFake(() => deferredEOT); const testRun = typeMoq.Mock.ofType(); testRun diff --git a/src/test/testing/testController/testCancellationRunAdapters.unit.test.ts b/src/test/testing/testController/testCancellationRunAdapters.unit.test.ts index 2aaffdda41df..e85cd2b62834 100644 --- a/src/test/testing/testController/testCancellationRunAdapters.unit.test.ts +++ b/src/test/testing/testController/testCancellationRunAdapters.unit.test.ts @@ -117,10 +117,16 @@ suite('Execution Flow Run Adapters', () => { deferredStartServer.resolve(); return Promise.resolve(54321); }); - // mock EOT token + // mock EOT token & ExecClose token const deferredEOT = createDeferred(); - const utilsCreateEOTStub: sinon.SinonStub = sinon.stub(util, 'createEOTDeferred'); - utilsCreateEOTStub.callsFake(() => deferredEOT); + const deferredExecClose = createDeferred(); + const utilsCreateEOTStub: sinon.SinonStub = sinon.stub(util, 'createTestingDeferred'); + utilsCreateEOTStub.callsFake(() => { + if (utilsCreateEOTStub.callCount === 1) { + return deferredEOT; + } + return deferredExecClose; + }); // set up test server testServer .setup((t) => t.onRunDataReceived(typeMoq.It.isAny(), typeMoq.It.isAny())) @@ -158,6 +164,11 @@ suite('Execution Flow Run Adapters', () => { const execServiceMock = typeMoq.Mock.ofType(); debugLauncher .setup((dl) => dl.launchDebugger(typeMoq.It.isAny(), typeMoq.It.isAny())) + .callback((_options, callback) => { + if (callback) { + callback(); + } + }) .returns(async () => { cancellationToken.cancel(); return Promise.resolve(); @@ -174,10 +185,16 @@ suite('Execution Flow Run Adapters', () => { deferredStartServer.resolve(); return Promise.resolve(54321); }); - // mock EOT token + // mock EOT token & ExecClose token const deferredEOT = createDeferred(); - const utilsCreateEOTStub: sinon.SinonStub = sinon.stub(util, 'createEOTDeferred'); - utilsCreateEOTStub.callsFake(() => deferredEOT); + const deferredExecClose = createDeferred(); + const utilsCreateEOTStub: sinon.SinonStub = sinon.stub(util, 'createTestingDeferred'); + utilsCreateEOTStub.callsFake(() => { + if (utilsCreateEOTStub.callCount === 1) { + return deferredEOT; + } + return deferredExecClose; + }); // set up test server testServer .setup((t) => t.onRunDataReceived(typeMoq.It.isAny(), typeMoq.It.isAny())) @@ -263,10 +280,16 @@ suite('Execution Flow Run Adapters', () => { deferredStartServer.resolve(); return Promise.resolve(54321); }); - // mock EOT token + // mock EOT token & ExecClose token const deferredEOT = createDeferred(); - const utilsCreateEOTStub: sinon.SinonStub = sinon.stub(util, 'createEOTDeferred'); - utilsCreateEOTStub.callsFake(() => deferredEOT); + const deferredExecClose = createDeferred(); + const utilsCreateEOTStub: sinon.SinonStub = sinon.stub(util, 'createTestingDeferred'); + utilsCreateEOTStub.callsFake(() => { + if (utilsCreateEOTStub.callCount === 1) { + return deferredEOT; + } + return deferredExecClose; + }); // set up test server const unittestAdapter = new UnittestTestExecutionAdapter( stubTestServer.object, @@ -331,10 +354,16 @@ suite('Execution Flow Run Adapters', () => { deferredStartServer.resolve(); return Promise.resolve(54321); }); - // mock EOT token + // mock EOT token & ExecClose token const deferredEOT = createDeferred(); - const utilsCreateEOTStub: sinon.SinonStub = sinon.stub(util, 'createEOTDeferred'); - utilsCreateEOTStub.callsFake(() => deferredEOT); + const deferredExecClose = createDeferred(); + const utilsCreateEOTStub: sinon.SinonStub = sinon.stub(util, 'createTestingDeferred'); + utilsCreateEOTStub.callsFake(() => { + if (utilsCreateEOTStub.callCount === 1) { + return deferredEOT; + } + return deferredExecClose; + }); // set up test server const unittestAdapter = new UnittestTestExecutionAdapter( stubTestServer.object,