Tests - Add more logging to test runner utility

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,

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);
     }
 

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

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);
@@ -89,7 +95,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,

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<T>(event: vscode.Event<T>): Promise<T> {
  * @returns The initialized test controller
  */
 export async function waitForTestExplorerReady(
-    testExplorer: TestExplorer
+    testExplorer: TestExplorer,
+    logger: SwiftLogger
 ): Promise<vscode.TestController> {
     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;
@@ -311,22 +279,37 @@ 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
     // of that TestRunProxy until the test run is complete.
     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<void> {
+    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;
+    }
+}