Add await for stdout (#22049)

eleanorjboyd · web-flow · commit 998a0a54a810 · 2023-09-25T15:01:50.000-07:00
Add await so all output is read before ending the run instance.
diff --git 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<ExecutionResult<string>>();
-                const result = execService.execObservable(args, spawnOptions);
+                const deferredTillExecClose = createDeferred<ExecutionResult<string>>();
+
+                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
@@ -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<void> {
+export function createTestingDeferred(): Deferred<void> {
     return createDeferred<void>();
 }
 
diff --git 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
@@ -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<void> {
-        const deferred = createDeferred<DiscoveredTestPayload>();
         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<ExecutionResult<string>>();
         const execArgs = ['-m', 'pytest', '-p', 'vscode_pytest', '--collect-only'].concat(pytestArgs);
         traceVerbose(`Running pytest discovery with command: ${execArgs.join(' ')}`);
+
+        const deferredTillExecClose: Deferred<void> = 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
@@ -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<ExecutionTestPayload> {
         const uuid = this.testServer.createUUID(uri.fsPath);
-        const deferredTillEOT: Deferred<void> = utils.createEOTDeferred();
+        // deferredTillEOT is resolved when all data sent over payload is received
+        const deferredTillEOT: Deferred<void> = 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<void> = 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<ExecutionResult<string>>();
-                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
@@ -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
@@ -66,6 +66,7 @@ suite('EOT tests', () => {
     let testController: TestController;
     let stubExecutionFactory: typeMoq.IMock<IPythonExecutionFactory>;
     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<Output<string>>(() => {
             /* 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
@@ -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>();
         testRun
diff --git a/src/test/testing/testController/testCancellationRunAdapters.unit.test.ts b/src/test/testing/testController/testCancellationRunAdapters.unit.test.ts

Original file line number	Diff line number	Diff line change
`@@ -43,7 +43,7 @@ export const JSONRPC_UUID_HEADER = 'Request-uuid';`
`43`	`43`	`export const JSONRPC_CONTENT_LENGTH_HEADER = 'Content-Length';`
`44`	`44`	`export const JSONRPC_CONTENT_TYPE_HEADER = 'Content-Type';`
`45`	`45`
`46`		`-export function createEOTDeferred(): Deferred<void> {`
	`46`	`+export function createTestingDeferred(): Deferred<void> {`
`47`	`47`	`return createDeferred<void>();`
`48`	`48`	`}`
`49`	`49`
Original file line number	Diff line number	Diff line change
`@@ -462,7 +462,6 @@ export class PythonTestController implements ITestController, IExtensionSingleAc`
`462`	`462`	`);`
`463`	`463`	`}`
`464`	`464`	`}`
`465`		`-`
`466`	`465`	`if (!settings.testing.pytestEnabled && !settings.testing.unittestEnabled) {`
`467`	`466`	`unconfiguredWorkspaces.push(workspace);`
`468`	`467`	`}`