adding extra log messages for rewrite debugging (#21352)

eleanorjboyd · web-flow · commit dbd0b73b9605 · 2023-05-31T15:36:44.000-07:00
These logs print errors and other bits of information which will be
helpful for debugging workflows of users where we need to get
information such as args or which step in the process they got to.
diff --git a/src/client/testing/testController/common/server.ts b/src/client/testing/testController/common/server.ts
@@ -9,7 +9,7 @@ import {
     IPythonExecutionFactory,
     SpawnOptions,
 } from '../../../common/process/types';
-import { traceLog } from '../../../logging';
+import { traceError, traceInfo, traceLog, traceVerbose } from '../../../logging';
 import { DataReceivedEvent, ITestServer, TestCommandOptions } from './types';
 import { ITestDebugLauncher, LaunchOptions } from '../../common/types';
 import { UNITTEST_PROVIDER } from '../../common/constants';
@@ -36,12 +36,12 @@ export class PythonTestServer implements ITestServer, Disposable {
                         const uuid = rpcHeaders.headers.get(JSONRPC_UUID_HEADER);
                         const totalContentLength = rpcHeaders.headers.get('Content-Length');
                         if (!uuid) {
-                            traceLog('On data received: Error occurred because payload UUID is undefined');
+                            traceError('On data received: Error occurred because payload UUID is undefined');
                             this._onDataReceived.fire({ uuid: '', data: '' });
                             return;
                         }
                         if (!this.uuids.includes(uuid)) {
-                            traceLog('On data received: Error occurred because the payload UUID is not recognized');
+                            traceError('On data received: Error occurred because the payload UUID is not recognized');
                             this._onDataReceived.fire({ uuid: '', data: '' });
                             return;
                         }
@@ -50,6 +50,7 @@ export class PythonTestServer implements ITestServer, Disposable {
                         const extractedData = rpcContent.extractedJSON;
                         if (extractedData.length === Number(totalContentLength)) {
                             // do not send until we have the full content
+                            traceVerbose(`Received data from test server: ${extractedData}`);
                             this._onDataReceived.fire({ uuid, data: extractedData });
                             this.uuids = this.uuids.filter((u) => u !== uuid);
                             buffer = Buffer.alloc(0);
@@ -58,7 +59,7 @@ export class PythonTestServer implements ITestServer, Disposable {
                         }
                     }
                 } catch (ex) {
-                    traceLog(`Error processing test server request: ${ex} observe`);
+                    traceError(`Error processing test server request: ${ex} observe`);
                     this._onDataReceived.fire({ uuid: '', data: '' });
                 }
             });
@@ -114,6 +115,8 @@ export class PythonTestServer implements ITestServer, Disposable {
             outputChannel: options.outChannel,
         };
 
+        const isRun = !options.testIds;
+
         // Create the Python environment in which to execute the command.
         const creationOptions: ExecutionFactoryCreateWithEnvironmentOptions = {
             allowEnvironmentFetchExceptions: false,
@@ -154,9 +157,16 @@ export class PythonTestServer implements ITestServer, Disposable {
                     token: options.token,
                     testProvider: UNITTEST_PROVIDER,
                 };
-
+                traceInfo(`Running DEBUG unittest with arguments: ${args}\r\n`);
                 await this.debugLauncher!.launchDebugger(launchOptions);
             } else {
+                if (isRun) {
+                    // This means it is running the test
+                    traceInfo(`Running unittests with arguments: ${args}\r\n`);
+                } else {
+                    // This means it is running discovery
+                    traceLog(`Discovering unittest tests with arguments: ${args}\r\n`);
+                }
                 await execService.exec(args, spawnOptions);
             }
         } catch (ex) {
diff --git a/src/client/testing/testController/controller.ts b/src/client/testing/testController/controller.ts
@@ -24,7 +24,7 @@ import { IConfigurationService, IDisposableRegistry, ITestOutputChannel, Resourc
 import { DelayedTrigger, IDelayedTrigger } from '../../common/utils/delayTrigger';
 import { noop } from '../../common/utils/misc';
 import { IInterpreterService } from '../../interpreter/contracts';
-import { traceError, traceVerbose } from '../../logging';
+import { traceError, traceInfo, traceVerbose } from '../../logging';
 import { IEventNamePropertyMapping, sendTelemetryEvent } from '../../telemetry';
 import { EventName } from '../../telemetry/constants';
 import { PYTEST_PROVIDER, UNITTEST_PROVIDER } from '../common/constants';
@@ -243,14 +243,14 @@ export class PythonTestController implements ITestController, IExtensionSingleAc
         this.refreshingStartedEvent.fire();
         if (uri) {
             const settings = this.configSettings.getSettings(uri);
-            traceVerbose(`Testing: Refreshing test data for ${uri.fsPath}`);
+            const workspace = this.workspaceService.getWorkspaceFolder(uri);
+            traceInfo(`Discover tests for workspace name: ${workspace?.name} - uri: ${uri.fsPath}`);
+            // Ensure we send test telemetry if it gets disabled again
+            this.sendTestDisabledTelemetry = true;
+            // ** experiment to roll out NEW test discovery mechanism
             if (settings.testing.pytestEnabled) {
-                // Ensure we send test telemetry if it gets disabled again
-                this.sendTestDisabledTelemetry = true;
-                // ** experiment to roll out NEW test discovery mechanism
                 if (pythonTestAdapterRewriteEnabled(this.serviceContainer)) {
-                    const workspace = this.workspaceService.getWorkspaceFolder(uri);
-                    traceVerbose(`Discover tests for workspace name: ${workspace?.name} - uri: ${uri.fsPath}`);
+                    traceInfo(`Running discovery for pytest using the new test adapter.`);
                     const testAdapter =
                         this.testAdapters.get(uri) || (this.testAdapters.values().next().value as WorkspaceTestAdapter);
                     testAdapter.discoverTests(
@@ -263,12 +263,8 @@ export class PythonTestController implements ITestController, IExtensionSingleAc
                     await this.pytest.refreshTestData(this.testController, uri, this.refreshCancellation.token);
                 }
             } else if (settings.testing.unittestEnabled) {
-                // ** Ensure we send test telemetry if it gets disabled again
-                this.sendTestDisabledTelemetry = true;
-                // ** experiment to roll out NEW test discovery mechanism
                 if (pythonTestAdapterRewriteEnabled(this.serviceContainer)) {
-                    const workspace = this.workspaceService.getWorkspaceFolder(uri);
-                    traceVerbose(`Discover tests for workspace name: ${workspace?.name} - uri: ${uri.fsPath}`);
+                    traceInfo(`Running discovery for unittest using the new test adapter.`);
                     const testAdapter =
                         this.testAdapters.get(uri) || (this.testAdapters.values().next().value as WorkspaceTestAdapter);
                     testAdapter.discoverTests(
@@ -288,7 +284,6 @@ export class PythonTestController implements ITestController, IExtensionSingleAc
                 // If we are here we may have to remove an existing node from the tree
                 // This handles the case where user removes test settings. Which should remove the
                 // tests for that particular case from the tree view
-                const workspace = this.workspaceService.getWorkspaceFolder(uri);
                 if (workspace) {
                     const toDelete: string[] = [];
                     this.testController.items.forEach((i: TestItem) => {
diff --git a/src/client/testing/testController/pytest/pytestDiscoveryAdapter.ts b/src/client/testing/testController/pytest/pytestDiscoveryAdapter.ts
@@ -10,7 +10,7 @@ import {
 import { IConfigurationService, ITestOutputChannel } from '../../../common/types';
 import { createDeferred, Deferred } from '../../../common/utils/async';
 import { EXTENSION_ROOT_DIR } from '../../../constants';
-import { traceVerbose } from '../../../logging';
+import { traceError, traceLog, traceVerbose } from '../../../logging';
 import { DataReceivedEvent, DiscoveredTestPayload, ITestDiscoveryAdapter, ITestServer } from '../common/types';
 
 /**
@@ -80,11 +80,12 @@ export class PytestTestDiscoveryAdapter implements ITestDiscoveryAdapter {
             resource: uri,
         };
         const execService = await executionFactory.createActivatedEnvironment(creationOptions);
-        execService
-            .exec(['-m', 'pytest', '-p', 'vscode_pytest', '--collect-only'].concat(pytestArgs), spawnOptions)
-            .catch((ex) => {
-                deferred.reject(ex as Error);
-            });
+        const discoveryArgs = ['-m', 'pytest', '-p', 'vscode_pytest', '--collect-only'].concat(pytestArgs);
+        traceLog(`Discovering pytest tests with arguments: ${discoveryArgs.join(' ')}`);
+        execService.exec(discoveryArgs, spawnOptions).catch((ex) => {
+            traceError(`Error occurred while discovering tests: ${ex}`);
+            deferred.reject(ex as Error);
+        });
         return deferred.promise;
     }
 }
diff --git a/src/client/testing/testController/pytest/pytestExecutionAdapter.ts b/src/client/testing/testController/pytest/pytestExecutionAdapter.ts
@@ -6,7 +6,7 @@ import * as path from 'path';
 import * as net from 'net';
 import { IConfigurationService, ITestOutputChannel } from '../../../common/types';
 import { createDeferred, Deferred } from '../../../common/utils/async';
-import { traceError, traceLog, traceVerbose } from '../../../logging';
+import { traceError, traceInfo, traceLog, traceVerbose } from '../../../logging';
 import { DataReceivedEvent, ExecutionTestPayload, ITestExecutionAdapter, ITestServer } from '../common/types';
 import {
     ExecutionFactoryCreateWithEnvironmentOptions,
@@ -21,7 +21,7 @@ import { EXTENSION_ROOT_DIR } from '../../../common/constants';
 // eslint-disable-next-line @typescript-eslint/no-explicit-any
 // (global as any).EXTENSION_ROOT_DIR = EXTENSION_ROOT_DIR;
 /**
- * Wrapper Class for pytest test execution. This is where we call `runTestCommand`?
+ * Wrapper Class for pytest test execution..
  */
 
 export class PytestTestExecutionAdapter implements ITestExecutionAdapter {
@@ -52,7 +52,6 @@ export class PytestTestExecutionAdapter implements ITestExecutionAdapter {
         executionFactory?: IPythonExecutionFactory,
         debugLauncher?: ITestDebugLauncher,
     ): Promise<ExecutionTestPayload> {
-        traceVerbose(uri, testIds, debugBool);
         if (executionFactory !== undefined) {
             // ** new version of run tests.
             return this.runTestsNew(uri, testIds, debugBool, executionFactory, debugLauncher);
@@ -120,41 +119,43 @@ export class PytestTestExecutionAdapter implements ITestExecutionAdapter {
             const testData = JSON.stringify(testIds);
             const headers = [`Content-Length: ${Buffer.byteLength(testData)}`, 'Content-Type: application/json'];
             const payload = `${headers.join('\r\n')}\r\n\r\n${testData}`;
+            traceLog(`Running pytest execution for the following test ids: ${testIds}`);
 
             let pytestRunTestIdsPort: string | undefined;
             const startServer = (): Promise<number> =>
                 new Promise((resolve, reject) => {
                     const server = net.createServer((socket: net.Socket) => {
                         socket.on('end', () => {
-                            traceLog('Client disconnected');
+                            traceVerbose('Client disconnected for pytest test ids server');
                         });
                     });
 
                     server.listen(0, () => {
                         const { port } = server.address() as net.AddressInfo;
-                        traceLog(`Server listening on port ${port}`);
+                        traceVerbose(`Server listening on port ${port} for pytest test ids server`);
                         resolve(port);
                     });
 
                     server.on('error', (error: Error) => {
+                        traceError('Error starting server for pytest test ids server:', error);
                         reject(error);
                     });
                     server.on('connection', (socket: net.Socket) => {
                         socket.write(payload);
-                        traceLog('payload sent', payload);
+                        traceVerbose('payload sent for pytest execution', payload);
                     });
                 });
 
             // Start the server and wait until it is listening
             await startServer()
                 .then((assignedPort) => {
-                    traceLog(`Server started and listening on port ${assignedPort}`);
+                    traceVerbose(`Server started for pytest test ids server and listening on port ${assignedPort}`);
                     pytestRunTestIdsPort = assignedPort.toString();
                     if (spawnOptions.extraVariables)
                         spawnOptions.extraVariables.RUN_TEST_IDS_PORT = pytestRunTestIdsPort;
                 })
                 .catch((error) => {
-                    traceError('Error starting server:', error);
+                    traceError('Error starting server for pytest test ids server:', error);
                 });
 
             if (debugBool) {
@@ -169,20 +170,21 @@ export class PytestTestExecutionAdapter implements ITestExecutionAdapter {
                     pytestUUID,
                     pytestRunTestIdsPort,
                 };
-                traceVerbose(`Running debug test with arguments: ${testArgs.join(' ')}\r\n`);
+                traceInfo(`Running DEBUG pytest with arguments: ${testArgs.join(' ')}\r\n`);
                 await debugLauncher!.launchDebugger(launchOptions);
             } else {
                 // 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 pytests with arguments: ${runArgs.join(' ')}\r\n`);
 
                 await execService?.exec(runArgs, spawnOptions).catch((ex) => {
                     traceError(`Error while running tests: ${testIds}\r\n${ex}\r\n\r\n`);
                     return Promise.reject(ex);
                 });
             }
         } catch (ex) {
-            traceVerbose(`Error while running tests: ${testIds}\r\n${ex}\r\n\r\n`);
+            traceError(`Error while running tests: ${testIds}\r\n${ex}\r\n\r\n`);
             return Promise.reject(ex);
         }
 
diff --git a/src/client/testing/testController/unittest/testDiscoveryAdapter.ts b/src/client/testing/testController/unittest/testDiscoveryAdapter.ts
@@ -14,6 +14,7 @@ import {
     TestCommandOptions,
     TestDiscoveryCommand,
 } from '../common/types';
+import { traceInfo } from '../../../logging';
 
 /**
  * Wrapper class for unittest test discovery. This is where we call `runTestCommand`.
@@ -61,6 +62,7 @@ export class UnittestTestDiscoveryAdapter implements ITestDiscoveryAdapter {
 
         // Send the test command to the server.
         // The server will fire an onDataReceived event once it gets a response.
+        traceInfo(`Sending discover unittest script to server.`);
         this.testServer.sendCommand(options);
 
         return deferred.promise;
diff --git a/src/client/testing/testController/workspaceTestAdapter.ts b/src/client/testing/testController/workspaceTestAdapter.ts
@@ -101,14 +101,14 @@ export class WorkspaceTestAdapter {
             const testCaseIds = Array.from(testCaseIdsSet);
             // ** execution factory only defined for new rewrite way
             if (executionFactory !== undefined) {
+                traceVerbose('executionFactory defined');
                 rawTestExecData = await this.executionAdapter.runTests(
                     this.workspaceUri,
                     testCaseIds,
                     debugBool,
                     executionFactory,
                     debugLauncher,
                 );
-                traceVerbose('executionFactory defined');
             } else {
                 rawTestExecData = await this.executionAdapter.runTests(this.workspaceUri, testCaseIds, debugBool);
             }
@@ -300,6 +300,7 @@ export class WorkspaceTestAdapter {
         try {
             // ** execution factory only defined for new rewrite way
             if (executionFactory !== undefined) {
+                traceVerbose('executionFactory defined');
                 rawTestData = await this.discoveryAdapter.discoverTests(this.workspaceUri, executionFactory);
             } else {
                 rawTestData = await this.discoveryAdapter.discoverTests(this.workspaceUri);
