Tests - Add more logging to test runner utility (#1882)

* 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.

Increase the timeout for the test explorer integration
tests on windows, as sourcekit-lsp can take > 10 minutes
to index on 6.0

Author: plemarquand

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