From 9239e938470511cafb3bd7b9060e888de8f441f2 Mon Sep 17 00:00:00 2001 From: Paul LeMarquand Date: Fri, 10 Oct 2025 09:22:04 -0400 Subject: [PATCH 1/3] Tests - Add more logging to test runner utility Occasionally the tests that use the `runTest` utility method to test running tests in VS Code will time out. Add more logging to help pinpoint the issue. --- .../testexplorer/utilities.ts | 29 ++++++++++++++----- 1 file changed, 22 insertions(+), 7 deletions(-) diff --git a/test/integration-tests/testexplorer/utilities.ts b/test/integration-tests/testexplorer/utilities.ts index cfed0d214..be04df0ef 100644 --- a/test/integration-tests/testexplorer/utilities.ts +++ b/test/integration-tests/testexplorer/utilities.ts @@ -311,7 +311,7 @@ export async function runTest( const testItems = gatherTests(testExplorer.controller, ...tests); const request = new vscode.TestRunRequest(testItems); - logger.info(`runTest: configuring test run with ${testItems}`); + logger.info(`runTest: configuring test run with ${testItems.map(t => t.id)}`); // The first promise is the return value, the second promise builds and runs // the tests, populating the TestRunProxy with results and blocking the return @@ -319,14 +319,29 @@ export async function runTest( return ( await Promise.all([ eventPromise(testExplorer.onCreateTestRun).then(run => { - logger.info(`runTest: created test run with items ${run.testItems}`); + logger.info(`runTest: created test run with items ${run.testItems.map(t => t.id)}`); return run; }), - targetProfile - .runHandler(request, new vscode.CancellationTokenSource().token) - ?.then(() => { - logger.info(`runTest: completed running tests`); - }), + performRun(targetProfile, request, logger), ]) )[0]; } + +async function performRun( + targetProfile: vscode.TestRunProfile, + request: vscode.TestRunRequest, + logger: SwiftLogger +): Promise { + const run = targetProfile.runHandler(request, new vscode.CancellationTokenSource().token); + if (!run) { + throw new Error("No test run was created"); + } + logger.info(`runTest: starting running tests`); + try { + await run; + logger.info(`runTest: completed running tests`); + } catch (e) { + logger.error(`runTest: error running tests: ${e}`); + throw e; + } +} From 899eb8b67aa86a1e8ff88762fa5c4ce9e1ba1591 Mon Sep 17 00:00:00 2001 From: Paul LeMarquand Date: Fri, 10 Oct 2025 12:07:57 -0400 Subject: [PATCH 2/3] More logging and set the rolling log level to 'debug' --- assets/test/.vscode/settings.json | 1 + src/TestExplorer/TestExplorer.ts | 20 ++++++++ src/logging/RollingLogTransport.ts | 2 +- .../TestExplorerIntegration.test.ts | 2 +- .../testexplorer/utilities.ts | 46 +++---------------- 5 files changed, 30 insertions(+), 41 deletions(-) diff --git a/assets/test/.vscode/settings.json b/assets/test/.vscode/settings.json index 5ac0aa56a..4ed70d281 100644 --- a/assets/test/.vscode/settings.json +++ b/assets/test/.vscode/settings.json @@ -7,6 +7,7 @@ "-Xswiftc", "-DTEST_ARGUMENT_SET_VIA_TEST_BUILD_ARGUMENTS_SETTING" ], + "swift.outputChannelLogLevel": "debug", "lldb.verboseLogging": true, "lldb.launch.terminal": "external", "lldb-dap.detachOnError": true, diff --git a/src/TestExplorer/TestExplorer.ts b/src/TestExplorer/TestExplorer.ts index 71c88627e..df06e9763 100644 --- a/src/TestExplorer/TestExplorer.ts +++ b/src/TestExplorer/TestExplorer.ts @@ -280,6 +280,7 @@ export class TestExplorer { tests: TestDiscovery.TestClass[], uri?: vscode.Uri ) { + this.logger.debug("Updating tests in test explorer", "Test Discovery"); TestDiscovery.updateTests(controller, tests, uri); this.onTestItemsDidChangeEmitter.fire(controller); } @@ -382,6 +383,10 @@ export class TestExplorer { explorer.deleteErrorTestItem(); const tests = parseTestsFromSwiftTestListOutput(stdout); + this.logger.debug( + `Discovered ${tests.length} top level tests via 'swift test --list-tests', updating test explorer`, + "Test Discovery" + ); explorer.updateTests(explorer.controller, tests); } ); @@ -438,18 +443,33 @@ export class TestExplorer { * Discover tests */ private async discoverTestsInWorkspaceLSP(token: vscode.CancellationToken) { + this.logger.debug("Discovering tests in workspace via LSP", "Test Discovery"); + const tests = await this.lspTestDiscovery.getWorkspaceTests( this.folderContext.swiftPackage ); + if (token.isCancellationRequested) { + this.logger.info("Test discovery cancelled", "Test Discovery"); return; } + this.logger.debug( + `Discovered ${tests.length} top level tests, updating test explorer`, + "Test Discovery" + ); + await TestDiscovery.updateTestsFromClasses( this.controller, this.folderContext.swiftPackage, tests ); + + this.logger.debug( + "Emitting test item change after LSP workspace test discovery", + "Test Discovery" + ); + this.onTestItemsDidChangeEmitter.fire(this.controller); } diff --git a/src/logging/RollingLogTransport.ts b/src/logging/RollingLogTransport.ts index acf2e5557..519a79ce9 100644 --- a/src/logging/RollingLogTransport.ts +++ b/src/logging/RollingLogTransport.ts @@ -22,7 +22,7 @@ const Transport: typeof TransportType = require("winston-transport"); export class RollingLogTransport extends Transport { constructor(private rollingLog: RollingLog) { super(); - this.level = "info"; // This log is used for testing, we don't want to hold verbose log messages + this.level = "debug"; } // eslint-disable-next-line @typescript-eslint/no-explicit-any diff --git a/test/integration-tests/testexplorer/TestExplorerIntegration.test.ts b/test/integration-tests/testexplorer/TestExplorerIntegration.test.ts index 76b7d1de3..a35129386 100644 --- a/test/integration-tests/testexplorer/TestExplorerIntegration.test.ts +++ b/test/integration-tests/testexplorer/TestExplorerIntegration.test.ts @@ -89,7 +89,7 @@ tag("large").suite("Test Explorer Suite", function () { // Set up the listener before bringing the text explorer in to focus, // which starts searching the workspace for tests. await logger("Waiting for test explorer to be ready", () => - waitForTestExplorerReady(testExplorer) + waitForTestExplorerReady(testExplorer, workspaceContext.logger) ); }, requiresLSP: true, diff --git a/test/integration-tests/testexplorer/utilities.ts b/test/integration-tests/testexplorer/utilities.ts index be04df0ef..610b8f52a 100644 --- a/test/integration-tests/testexplorer/utilities.ts +++ b/test/integration-tests/testexplorer/utilities.ts @@ -21,46 +21,9 @@ import { reduceTestItemChildren } from "@src/TestExplorer/TestUtils"; import { WorkspaceContext } from "@src/WorkspaceContext"; import { SwiftLogger } from "@src/logging/SwiftLogger"; -import { testAssetUri } from "../../fixtures"; -import { - SettingsMap, - activateExtension, - deactivateExtension, - updateSettings, -} from "../utilities/testutilities"; - // eslint-disable-next-line @typescript-eslint/no-require-imports import stripAnsi = require("strip-ansi"); -/** - * Sets up a test that leverages the TestExplorer, returning the TestExplorer, - * WorkspaceContext and a callback to revert the settings back to their original values. - * @param settings Optional extension settings to set before the test starts. - * @returns Object containing the TestExplorer, WorkspaceContext and a callback to revert - * the settings back to their original values. - */ -export async function setupTestExplorerTest(currentTest?: Mocha.Test, settings: SettingsMap = {}) { - const settingsTeardown = await updateSettings(settings); - - const testProject = testAssetUri("defaultPackage"); - - const workspaceContext = await activateExtension(currentTest); - const testExplorer = testExplorerFor(workspaceContext, testProject); - - // Set up the listener before bringing the text explorer in to focus, - // which starts searching the workspace for tests. - await waitForTestExplorerReady(testExplorer); - - return { - settingsTeardown: async () => { - await settingsTeardown(); - await deactivateExtension(); - }, - workspaceContext, - testExplorer, - }; -} - /** * Returns the TestExplorer for the given workspace and package folder. * @@ -215,10 +178,15 @@ export function eventPromise(event: vscode.Event): Promise { * @returns The initialized test controller */ export async function waitForTestExplorerReady( - testExplorer: TestExplorer + testExplorer: TestExplorer, + logger: SwiftLogger ): Promise { await vscode.commands.executeCommand("workbench.view.testing.focus"); - const controller = await (testExplorer.controller.items.size === 0 + const noExistingTests = testExplorer.controller.items.size === 0; + logger.info( + `waitForTestExplorerReady: Found ${testExplorer.controller.items.size} existing top level test(s)` + ); + const controller = await (noExistingTests ? eventPromise(testExplorer.onTestItemsDidChange) : Promise.resolve(testExplorer.controller)); return controller; From aa91c59685281cae3f8c47445d25702350382a65 Mon Sep 17 00:00:00 2001 From: Paul LeMarquand Date: Sun, 12 Oct 2025 15:30:06 -0400 Subject: [PATCH 3/3] Increase test explorer setup timeout --- .../testexplorer/TestExplorerIntegration.test.ts | 6 ++++++ 1 file changed, 6 insertions(+) diff --git a/test/integration-tests/testexplorer/TestExplorerIntegration.test.ts b/test/integration-tests/testexplorer/TestExplorerIntegration.test.ts index a35129386..70a15e837 100644 --- a/test/integration-tests/testexplorer/TestExplorerIntegration.test.ts +++ b/test/integration-tests/testexplorer/TestExplorerIntegration.test.ts @@ -66,6 +66,12 @@ tag("large").suite("Test Explorer Suite", function () { activateExtensionForSuite({ async setup(ctx) { + // It can take a very long time for sourcekit-lsp to index tests on Windows, + // especially w/ Swift 6.0. Wait for up to 25 minutes for the indexing to complete. + if (process.platform === "win32") { + this.timeout(25 * 60 * 1000); + } + workspaceContext = ctx; runTest = runTestWithLogging.bind(null, workspaceContext.logger); const logger = withLogging(ctx.logger);