Skip to content

Commit dbd0b73

Browse files
eleanorjboydeleanorjboyd
authored
adding extra log messages for rewrite debugging (#21352)
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.
1 parent d968b8c commit dbd0b73

6 files changed

Lines changed: 46 additions & 35 deletions

File tree

‎src/client/testing/testController/common/server.ts‎

Lines changed: 15 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -9,7 +9,7 @@ import {
99
IPythonExecutionFactory,
1010
SpawnOptions,
1111
} from '../../../common/process/types';
12-
import { traceLog } from '../../../logging';
12+
import { traceError, traceInfo, traceLog, traceVerbose } from '../../../logging';
1313
import { DataReceivedEvent, ITestServer, TestCommandOptions } from './types';
1414
import { ITestDebugLauncher, LaunchOptions } from '../../common/types';
1515
import { UNITTEST_PROVIDER } from '../../common/constants';
@@ -36,12 +36,12 @@ export class PythonTestServer implements ITestServer, Disposable {
3636
const uuid = rpcHeaders.headers.get(JSONRPC_UUID_HEADER);
3737
const totalContentLength = rpcHeaders.headers.get('Content-Length');
3838
if (!uuid) {
39-
traceLog('On data received: Error occurred because payload UUID is undefined');
39+
traceError('On data received: Error occurred because payload UUID is undefined');
4040
this._onDataReceived.fire({ uuid: '', data: '' });
4141
return;
4242
}
4343
if (!this.uuids.includes(uuid)) {
44-
traceLog('On data received: Error occurred because the payload UUID is not recognized');
44+
traceError('On data received: Error occurred because the payload UUID is not recognized');
4545
this._onDataReceived.fire({ uuid: '', data: '' });
4646
return;
4747
}
@@ -50,6 +50,7 @@ export class PythonTestServer implements ITestServer, Disposable {
5050
const extractedData = rpcContent.extractedJSON;
5151
if (extractedData.length === Number(totalContentLength)) {
5252
// do not send until we have the full content
53+
traceVerbose(`Received data from test server: ${extractedData}`);
5354
this._onDataReceived.fire({ uuid, data: extractedData });
5455
this.uuids = this.uuids.filter((u) => u !== uuid);
5556
buffer = Buffer.alloc(0);
@@ -58,7 +59,7 @@ export class PythonTestServer implements ITestServer, Disposable {
5859
}
5960
}
6061
} catch (ex) {
61-
traceLog(`Error processing test server request: ${ex} observe`);
62+
traceError(`Error processing test server request: ${ex} observe`);
6263
this._onDataReceived.fire({ uuid: '', data: '' });
6364
}
6465
});
@@ -114,6 +115,8 @@ export class PythonTestServer implements ITestServer, Disposable {
114115
outputChannel: options.outChannel,
115116
};
116117

118+
const isRun = !options.testIds;
119+
117120
// Create the Python environment in which to execute the command.
118121
const creationOptions: ExecutionFactoryCreateWithEnvironmentOptions = {
119122
allowEnvironmentFetchExceptions: false,
@@ -154,9 +157,16 @@ export class PythonTestServer implements ITestServer, Disposable {
154157
token: options.token,
155158
testProvider: UNITTEST_PROVIDER,
156159
};
157-
160+
traceInfo(`Running DEBUG unittest with arguments: ${args}\r\n`);
158161
await this.debugLauncher!.launchDebugger(launchOptions);
159162
} else {
163+
if (isRun) {
164+
// This means it is running the test
165+
traceInfo(`Running unittests with arguments: ${args}\r\n`);
166+
} else {
167+
// This means it is running discovery
168+
traceLog(`Discovering unittest tests with arguments: ${args}\r\n`);
169+
}
160170
await execService.exec(args, spawnOptions);
161171
}
162172
} catch (ex) {

‎src/client/testing/testController/controller.ts‎

Lines changed: 8 additions & 13 deletions
Original file line numberDiff line numberDiff line change
@@ -24,7 +24,7 @@ import { IConfigurationService, IDisposableRegistry, ITestOutputChannel, Resourc
2424
import { DelayedTrigger, IDelayedTrigger } from '../../common/utils/delayTrigger';
2525
import { noop } from '../../common/utils/misc';
2626
import { IInterpreterService } from '../../interpreter/contracts';
27-
import { traceError, traceVerbose } from '../../logging';
27+
import { traceError, traceInfo, traceVerbose } from '../../logging';
2828
import { IEventNamePropertyMapping, sendTelemetryEvent } from '../../telemetry';
2929
import { EventName } from '../../telemetry/constants';
3030
import { PYTEST_PROVIDER, UNITTEST_PROVIDER } from '../common/constants';
@@ -243,14 +243,14 @@ export class PythonTestController implements ITestController, IExtensionSingleAc
243243
this.refreshingStartedEvent.fire();
244244
if (uri) {
245245
const settings = this.configSettings.getSettings(uri);
246-
traceVerbose(`Testing: Refreshing test data for ${uri.fsPath}`);
246+
const workspace = this.workspaceService.getWorkspaceFolder(uri);
247+
traceInfo(`Discover tests for workspace name: ${workspace?.name} - uri: ${uri.fsPath}`);
248+
// Ensure we send test telemetry if it gets disabled again
249+
this.sendTestDisabledTelemetry = true;
250+
// ** experiment to roll out NEW test discovery mechanism
247251
if (settings.testing.pytestEnabled) {
248-
// Ensure we send test telemetry if it gets disabled again
249-
this.sendTestDisabledTelemetry = true;
250-
// ** experiment to roll out NEW test discovery mechanism
251252
if (pythonTestAdapterRewriteEnabled(this.serviceContainer)) {
252-
const workspace = this.workspaceService.getWorkspaceFolder(uri);
253-
traceVerbose(`Discover tests for workspace name: ${workspace?.name} - uri: ${uri.fsPath}`);
253+
traceInfo(`Running discovery for pytest using the new test adapter.`);
254254
const testAdapter =
255255
this.testAdapters.get(uri) || (this.testAdapters.values().next().value as WorkspaceTestAdapter);
256256
testAdapter.discoverTests(
@@ -263,12 +263,8 @@ export class PythonTestController implements ITestController, IExtensionSingleAc
263263
await this.pytest.refreshTestData(this.testController, uri, this.refreshCancellation.token);
264264
}
265265
} else if (settings.testing.unittestEnabled) {
266-
// ** Ensure we send test telemetry if it gets disabled again
267-
this.sendTestDisabledTelemetry = true;
268-
// ** experiment to roll out NEW test discovery mechanism
269266
if (pythonTestAdapterRewriteEnabled(this.serviceContainer)) {
270-
const workspace = this.workspaceService.getWorkspaceFolder(uri);
271-
traceVerbose(`Discover tests for workspace name: ${workspace?.name} - uri: ${uri.fsPath}`);
267+
traceInfo(`Running discovery for unittest using the new test adapter.`);
272268
const testAdapter =
273269
this.testAdapters.get(uri) || (this.testAdapters.values().next().value as WorkspaceTestAdapter);
274270
testAdapter.discoverTests(
@@ -288,7 +284,6 @@ export class PythonTestController implements ITestController, IExtensionSingleAc
288284
// If we are here we may have to remove an existing node from the tree
289285
// This handles the case where user removes test settings. Which should remove the
290286
// tests for that particular case from the tree view
291-
const workspace = this.workspaceService.getWorkspaceFolder(uri);
292287
if (workspace) {
293288
const toDelete: string[] = [];
294289
this.testController.items.forEach((i: TestItem) => {

‎src/client/testing/testController/pytest/pytestDiscoveryAdapter.ts‎

Lines changed: 7 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -10,7 +10,7 @@ import {
1010
import { IConfigurationService, ITestOutputChannel } from '../../../common/types';
1111
import { createDeferred, Deferred } from '../../../common/utils/async';
1212
import { EXTENSION_ROOT_DIR } from '../../../constants';
13-
import { traceVerbose } from '../../../logging';
13+
import { traceError, traceLog, traceVerbose } from '../../../logging';
1414
import { DataReceivedEvent, DiscoveredTestPayload, ITestDiscoveryAdapter, ITestServer } from '../common/types';
1515

1616
/**
@@ -80,11 +80,12 @@ export class PytestTestDiscoveryAdapter implements ITestDiscoveryAdapter {
8080
resource: uri,
8181
};
8282
const execService = await executionFactory.createActivatedEnvironment(creationOptions);
83-
execService
84-
.exec(['-m', 'pytest', '-p', 'vscode_pytest', '--collect-only'].concat(pytestArgs), spawnOptions)
85-
.catch((ex) => {
86-
deferred.reject(ex as Error);
87-
});
83+
const discoveryArgs = ['-m', 'pytest', '-p', 'vscode_pytest', '--collect-only'].concat(pytestArgs);
84+
traceLog(`Discovering pytest tests with arguments: ${discoveryArgs.join(' ')}`);
85+
execService.exec(discoveryArgs, spawnOptions).catch((ex) => {
86+
traceError(`Error occurred while discovering tests: ${ex}`);
87+
deferred.reject(ex as Error);
88+
});
8889
return deferred.promise;
8990
}
9091
}

‎src/client/testing/testController/pytest/pytestExecutionAdapter.ts‎

Lines changed: 12 additions & 10 deletions
Original file line numberDiff line numberDiff line change
@@ -6,7 +6,7 @@ import * as path from 'path';
66
import * as net from 'net';
77
import { IConfigurationService, ITestOutputChannel } from '../../../common/types';
88
import { createDeferred, Deferred } from '../../../common/utils/async';
9-
import { traceError, traceLog, traceVerbose } from '../../../logging';
9+
import { traceError, traceInfo, traceLog, traceVerbose } from '../../../logging';
1010
import { DataReceivedEvent, ExecutionTestPayload, ITestExecutionAdapter, ITestServer } from '../common/types';
1111
import {
1212
ExecutionFactoryCreateWithEnvironmentOptions,
@@ -21,7 +21,7 @@ import { EXTENSION_ROOT_DIR } from '../../../common/constants';
2121
// eslint-disable-next-line @typescript-eslint/no-explicit-any
2222
// (global as any).EXTENSION_ROOT_DIR = EXTENSION_ROOT_DIR;
2323
/**
24-
* Wrapper Class for pytest test execution. This is where we call `runTestCommand`?
24+
* Wrapper Class for pytest test execution..
2525
*/
2626

2727
export class PytestTestExecutionAdapter implements ITestExecutionAdapter {
@@ -52,7 +52,6 @@ export class PytestTestExecutionAdapter implements ITestExecutionAdapter {
5252
executionFactory?: IPythonExecutionFactory,
5353
debugLauncher?: ITestDebugLauncher,
5454
): Promise<ExecutionTestPayload> {
55-
traceVerbose(uri, testIds, debugBool);
5655
if (executionFactory !== undefined) {
5756
// ** new version of run tests.
5857
return this.runTestsNew(uri, testIds, debugBool, executionFactory, debugLauncher);
@@ -120,41 +119,43 @@ export class PytestTestExecutionAdapter implements ITestExecutionAdapter {
120119
const testData = JSON.stringify(testIds);
121120
const headers = [`Content-Length: ${Buffer.byteLength(testData)}`, 'Content-Type: application/json'];
122121
const payload = `${headers.join('\r\n')}\r\n\r\n${testData}`;
122+
traceLog(`Running pytest execution for the following test ids: ${testIds}`);
123123

124124
let pytestRunTestIdsPort: string | undefined;
125125
const startServer = (): Promise<number> =>
126126
new Promise((resolve, reject) => {
127127
const server = net.createServer((socket: net.Socket) => {
128128
socket.on('end', () => {
129-
traceLog('Client disconnected');
129+
traceVerbose('Client disconnected for pytest test ids server');
130130
});
131131
});
132132

133133
server.listen(0, () => {
134134
const { port } = server.address() as net.AddressInfo;
135-
traceLog(`Server listening on port ${port}`);
135+
traceVerbose(`Server listening on port ${port} for pytest test ids server`);
136136
resolve(port);
137137
});
138138

139139
server.on('error', (error: Error) => {
140+
traceError('Error starting server for pytest test ids server:', error);
140141
reject(error);
141142
});
142143
server.on('connection', (socket: net.Socket) => {
143144
socket.write(payload);
144-
traceLog('payload sent', payload);
145+
traceVerbose('payload sent for pytest execution', payload);
145146
});
146147
});
147148

148149
// Start the server and wait until it is listening
149150
await startServer()
150151
.then((assignedPort) => {
151-
traceLog(`Server started and listening on port ${assignedPort}`);
152+
traceVerbose(`Server started for pytest test ids server and listening on port ${assignedPort}`);
152153
pytestRunTestIdsPort = assignedPort.toString();
153154
if (spawnOptions.extraVariables)
154155
spawnOptions.extraVariables.RUN_TEST_IDS_PORT = pytestRunTestIdsPort;
155156
})
156157
.catch((error) => {
157-
traceError('Error starting server:', error);
158+
traceError('Error starting server for pytest test ids server:', error);
158159
});
159160

160161
if (debugBool) {
@@ -169,20 +170,21 @@ export class PytestTestExecutionAdapter implements ITestExecutionAdapter {
169170
pytestUUID,
170171
pytestRunTestIdsPort,
171172
};
172-
traceVerbose(`Running debug test with arguments: ${testArgs.join(' ')}\r\n`);
173+
traceInfo(`Running DEBUG pytest with arguments: ${testArgs.join(' ')}\r\n`);
173174
await debugLauncher!.launchDebugger(launchOptions);
174175
} else {
175176
// combine path to run script with run args
176177
const scriptPath = path.join(fullPluginPath, 'vscode_pytest', 'run_pytest_script.py');
177178
const runArgs = [scriptPath, ...testArgs];
179+
traceInfo(`Running pytests with arguments: ${runArgs.join(' ')}\r\n`);
178180

179181
await execService?.exec(runArgs, spawnOptions).catch((ex) => {
180182
traceError(`Error while running tests: ${testIds}\r\n${ex}\r\n\r\n`);
181183
return Promise.reject(ex);
182184
});
183185
}
184186
} catch (ex) {
185-
traceVerbose(`Error while running tests: ${testIds}\r\n${ex}\r\n\r\n`);
187+
traceError(`Error while running tests: ${testIds}\r\n${ex}\r\n\r\n`);
186188
return Promise.reject(ex);
187189
}
188190

‎src/client/testing/testController/unittest/testDiscoveryAdapter.ts‎

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -14,6 +14,7 @@ import {
1414
TestCommandOptions,
1515
TestDiscoveryCommand,
1616
} from '../common/types';
17+
import { traceInfo } from '../../../logging';
1718

1819
/**
1920
* Wrapper class for unittest test discovery. This is where we call `runTestCommand`.
@@ -61,6 +62,7 @@ export class UnittestTestDiscoveryAdapter implements ITestDiscoveryAdapter {
6162

6263
// Send the test command to the server.
6364
// The server will fire an onDataReceived event once it gets a response.
65+
traceInfo(`Sending discover unittest script to server.`);
6466
this.testServer.sendCommand(options);
6567

6668
return deferred.promise;

‎src/client/testing/testController/workspaceTestAdapter.ts‎

Lines changed: 2 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -101,14 +101,14 @@ export class WorkspaceTestAdapter {
101101
const testCaseIds = Array.from(testCaseIdsSet);
102102
// ** execution factory only defined for new rewrite way
103103
if (executionFactory !== undefined) {
104+
traceVerbose('executionFactory defined');
104105
rawTestExecData = await this.executionAdapter.runTests(
105106
this.workspaceUri,
106107
testCaseIds,
107108
debugBool,
108109
executionFactory,
109110
debugLauncher,
110111
);
111-
traceVerbose('executionFactory defined');
112112
} else {
113113
rawTestExecData = await this.executionAdapter.runTests(this.workspaceUri, testCaseIds, debugBool);
114114
}
@@ -300,6 +300,7 @@ export class WorkspaceTestAdapter {
300300
try {
301301
// ** execution factory only defined for new rewrite way
302302
if (executionFactory !== undefined) {
303+
traceVerbose('executionFactory defined');
303304
rawTestData = await this.discoveryAdapter.discoverTests(this.workspaceUri, executionFactory);
304305
} else {
305306
rawTestData = await this.discoveryAdapter.discoverTests(this.workspaceUri);

0 commit comments

Comments
 (0)