refactor(@angular/build): add debug logging to Vitest executor

clydin · clydin · commit ad2c14e52114 · 2026-03-03T12:14:39.000-05:00
This commit introduces a multi-level debug logging system within the Vitest test runner's executor. This logging is intended to aid in troubleshooting internal issues and provide deeper insights into the test execution process. Logging is controlled by the `NG_TEST_LOG` environment variable, which accepts numeric levels (0 for off, 1 for debug, 2 for verbose). Crucial lifecycle events and state changes in the `VitestExecutor` are now logged, such as constructor instantiation, build result processing (full and incremental), test re-run specifications, Vitest initialization details (including browser configuration, external configuration path, and included files), and executor disposal. These logs are guarded by the `logLevel` to prevent any performance penalties during normal execution. Furthermore, specific areas like incremental run file mappings and external dependency metadata are logged at a verbose level. (cherry picked from commit 2887d84)
diff --git a/packages/angular/build/src/builders/unit-test/runners/vitest/executor.ts b/packages/angular/build/src/builders/unit-test/runners/vitest/executor.ts
@@ -27,6 +27,11 @@ import { setupBrowserConfiguration } from './browser-provider';
 import { findVitestBaseConfig } from './configuration';
 import { createVitestConfigPlugin, createVitestPlugins } from './plugins';
 
+enum DebugLogLevel {
+  Info = 1,
+  Verbose = 2,
+}
+
 export class VitestExecutor implements TestExecutor {
   private vitest: Vitest | undefined;
   private normalizePath: ((id: string) => string) | undefined;
@@ -40,6 +45,7 @@ export class VitestExecutor implements TestExecutor {
     explicitBrowser: [],
     explicitServer: [],
   };
+  private readonly debugLevel: number;
 
   // This is a reverse map of the entry points created in `build-options.ts`.
   // It is used by the in-memory provider plugin to map the requested test file
@@ -54,27 +60,63 @@ export class VitestExecutor implements TestExecutor {
     testEntryPointMappings: Map<string, string> | undefined,
     logger: BuilderContext['logger'],
   ) {
+    const level = parseInt(process.env['NG_TEST_LOG'] ?? '0', 10);
+    this.debugLevel = isNaN(level) ? 0 : level;
+
     this.projectName = projectName;
     this.options = options;
     this.logger = logger;
 
+    this.debugLog(DebugLogLevel.Info, 'VitestExecutor instantiated.');
+    this.debugLog(DebugLogLevel.Verbose, 'NormalizedUnitTestBuilderOptions:', options);
+
     if (testEntryPointMappings) {
       for (const [entryPoint, testFile] of testEntryPointMappings) {
         this.testFileToEntryPoint.set(testFile, entryPoint);
         this.entryPointToTestFile.set(entryPoint + '.js', testFile);
       }
+      this.debugLog(
+        DebugLogLevel.Verbose,
+        'Test entry point mappings:',
+        Object.fromEntries(testEntryPointMappings),
+      );
     }
   }
 
+  private debugLog(level: DebugLogLevel, message: string, data?: object) {
+    if (this.debugLevel < level) {
+      return;
+    }
+
+    const formattedMessage = `[VitestExecutor:${DebugLogLevel[level]}] ${message}`;
+    // Custom formatting for data object to ensure it's readable
+    const logData = data ? JSON.stringify(data, null, 2) : '';
+    this.logger.info(`${formattedMessage}${logData ? `\n${logData}` : ''}`);
+  }
+
   async *execute(buildResult: FullResult | IncrementalResult): AsyncIterable<BuilderOutput> {
+    this.debugLog(DebugLogLevel.Info, `Executing test run (kind: ${buildResult.kind}).`);
     this.normalizePath ??= (await import('vite')).normalizePath;
 
     if (buildResult.kind === ResultKind.Full) {
       this.buildResultFiles.clear();
       for (const [path, file] of Object.entries(buildResult.files)) {
         this.buildResultFiles.set(this.normalizePath(path), file);
       }
+      this.debugLog(
+        DebugLogLevel.Info,
+        `Full build results received. Total files: ${this.buildResultFiles.size}.`,
+      );
     } else {
+      this.debugLog(
+        DebugLogLevel.Info,
+        `Incremental build results received.` +
+          `Added: ${buildResult.added.length}, Modified: ${buildResult.modified.length}, Removed: ${buildResult.removed.length}.`,
+      );
+      this.debugLog(DebugLogLevel.Verbose, 'Added files:', buildResult.added);
+      this.debugLog(DebugLogLevel.Verbose, 'Modified files:', buildResult.modified);
+      this.debugLog(DebugLogLevel.Verbose, 'Removed files:', buildResult.removed);
+
       for (const file of buildResult.removed) {
         this.buildResultFiles.delete(this.normalizePath(file.path));
       }
@@ -84,6 +126,7 @@ export class VitestExecutor implements TestExecutor {
     }
 
     updateExternalMetadata(buildResult, this.externalMetadata, undefined, true);
+    this.debugLog(DebugLogLevel.Verbose, 'Updated external metadata:', this.externalMetadata);
 
     // Reset the exit code to allow for a clean state.
     // This is necessary because Vitest may set the exit code on failure, which can
@@ -103,7 +146,16 @@ export class VitestExecutor implements TestExecutor {
         // We need to find the original source file path to pass to Vitest.
         const source = this.entryPointToTestFile.get(modifiedFile);
         if (source) {
+          this.debugLog(
+            DebugLogLevel.Verbose,
+            `Mapped output file '${modifiedFile}' to source file '${source}' for re-run.`,
+          );
           modifiedSourceFiles.add(source);
+        } else {
+          this.debugLog(
+            DebugLogLevel.Verbose,
+            `Could not map output file '${modifiedFile}' to a source file. It may not be a test file.`,
+          );
         }
         vitest.invalidateFile(
           this.normalizePath(path.join(this.options.workspaceRoot, modifiedFile)),
@@ -120,28 +172,41 @@ export class VitestExecutor implements TestExecutor {
       }
 
       if (specsToRerun.length > 0) {
+        this.debugLog(DebugLogLevel.Info, `Re-running ${specsToRerun.length} test specifications.`);
+        this.debugLog(DebugLogLevel.Verbose, 'Specs to rerun:', specsToRerun);
         testResults = await vitest.rerunTestSpecifications(specsToRerun);
+      } else {
+        this.debugLog(DebugLogLevel.Info, 'No test specifications to rerun.');
       }
     }
 
     // Check if all the tests pass to calculate the result
     const testModules = testResults?.testModules ?? this.vitest.state.getTestModules();
 
     let success = testModules.every((testModule) => testModule.ok());
+    let finalResultReason = 'All tests passed.';
+
     // Vitest does not return a failure result when coverage thresholds are not met.
     // Instead, it sets the process exit code to 1.
     // We check this exit code to determine if the test run should be considered a failure.
     if (success && process.exitCode === 1) {
       success = false;
+      finalResultReason = 'Test run failed due to unmet coverage thresholds.';
       // Reset the exit code to prevent it from carrying over to subsequent runs/builds
       process.exitCode = 0;
     }
 
+    this.debugLog(
+      DebugLogLevel.Info,
+      `Test run finished with success: ${success}. Reason: ${finalResultReason}`,
+    );
     yield { success };
   }
 
   async [Symbol.asyncDispose](): Promise<void> {
+    this.debugLog(DebugLogLevel.Info, 'Disposing VitestExecutor: Closing Vitest instance.');
     await this.vitest?.close();
+    this.debugLog(DebugLogLevel.Info, 'Vitest instance closed.');
   }
 
   private prepareSetupFiles(): string[] {
@@ -154,10 +219,13 @@ export class VitestExecutor implements TestExecutor {
       testSetupFiles.unshift('polyfills.js');
     }
 
+    this.debugLog(DebugLogLevel.Info, 'Prepared setup files:', testSetupFiles);
+
     return testSetupFiles;
   }
 
   private async initializeVitest(): Promise<Vitest> {
+    this.debugLog(DebugLogLevel.Info, 'Initializing Vitest.');
     const {
       coverage,
       reporters,
@@ -180,6 +248,10 @@ export class VitestExecutor implements TestExecutor {
       vitestNodeModule = await import('vitest/node');
     } catch (error: unknown) {
       assertIsError(error);
+      this.debugLog(
+        DebugLogLevel.Info,
+        `Failed to import 'vitest/node'. Error code: ${error.code}`,
+      );
       if (error.code !== 'ERR_MODULE_NOT_FOUND') {
         throw error;
       }
@@ -198,6 +270,9 @@ export class VitestExecutor implements TestExecutor {
       browserViewport,
     );
     if (browserOptions.errors?.length) {
+      this.debugLog(DebugLogLevel.Info, 'Browser configuration errors found.', {
+        errors: browserOptions.errors,
+      });
       throw new Error(browserOptions.errors.join('\n'));
     }
 
@@ -206,7 +281,14 @@ export class VitestExecutor implements TestExecutor {
         this.logger.info(message);
       }
     }
+    this.debugLog(DebugLogLevel.Info, 'Browser configuration complete.', {
+      config: browserOptions.browser,
+    });
 
+    this.debugLog(
+      DebugLogLevel.Info,
+      `Verifying build results. File count: ${this.buildResultFiles.size}.`,
+    );
     assert(
       this.buildResultFiles.size > 0,
       'buildResult must be available before initializing vitest',
@@ -234,6 +316,10 @@ export class VitestExecutor implements TestExecutor {
         ? await findVitestBaseConfig([projectRoot, workspaceRoot])
         : runnerConfig;
 
+    this.debugLog(DebugLogLevel.Info, 'External Vitest configuration path:', {
+      externalConfigPath,
+    });
+
     let project = projectName;
     if (debug && browserOptions.browser?.instances) {
       if (browserOptions.browser.instances.length > 1) {
@@ -245,6 +331,9 @@ export class VitestExecutor implements TestExecutor {
       // When running browser tests, Vitest appends the browser name to the project identifier.
       // The project name must match this augmented name to ensure the correct project is targeted.
       project = `${projectName} (${browserOptions.browser.instances[0].browser})`;
+      this.debugLog(DebugLogLevel.Info, 'Adjusted project name for debugging with browser:', {
+        project,
+      });
     }
 
     // Filter internal entries and setup files from the include list
@@ -255,43 +344,46 @@ export class VitestExecutor implements TestExecutor {
         !internalEntries.some((internal) => entry.startsWith(internal)) && !setupFileSet.has(entry)
       );
     });
+    this.debugLog(DebugLogLevel.Verbose, 'Included test files (after filtering):', include);
 
-    return startVitest(
-      'test',
-      undefined,
-      {
-        config: externalConfigPath,
-        root: workspaceRoot,
-        project,
-        outputFile,
-        cache: cacheOptions.enabled ? undefined : false,
-        testNamePattern: this.options.filter,
-        watch,
-        ...(typeof ui === 'boolean' ? { ui } : {}),
-        ...debugOptions,
-      },
-      {
-        // Note `.vitest` is auto appended to the path.
-        cacheDir: cacheOptions.path,
-        server: {
-          // Disable the actual file watcher. The boolean watch option above should still
-          // be enabled as it controls other internal behavior related to rerunning tests.
-          watch: null,
-        },
-        plugins: [
-          await createVitestConfigPlugin({
-            browser: browserOptions.browser,
-            coverage,
-            projectName,
-            projectSourceRoot,
-            optimizeDepsInclude: this.externalMetadata.implicitBrowser,
-            reporters,
-            setupFiles: testSetupFiles,
-            projectPlugins,
-            include,
-          }),
-        ],
+    const vitestConfig = {
+      config: externalConfigPath,
+      root: workspaceRoot,
+      project,
+      outputFile,
+      cache: cacheOptions.enabled ? undefined : (false as const),
+      testNamePattern: this.options.filter,
+      watch,
+      ...(typeof ui === 'boolean' ? { ui } : {}),
+      ...debugOptions,
+    };
+    const vitestServerConfig = {
+      // Note `.vitest` is auto appended to the path.
+      cacheDir: cacheOptions.path,
+      server: {
+        // Disable the actual file watcher. The boolean watch option above should still
+        // be enabled as it controls other internal behavior related to rerunning tests.
+        watch: null,
       },
-    );
+      plugins: [
+        await createVitestConfigPlugin({
+          browser: browserOptions.browser,
+          coverage,
+          projectName,
+          projectSourceRoot,
+          optimizeDepsInclude: this.externalMetadata.implicitBrowser,
+          reporters,
+          setupFiles: testSetupFiles,
+          projectPlugins,
+          include,
+        }),
+      ],
+    };
+
+    this.debugLog(DebugLogLevel.Info, 'Calling startVitest with final configuration.');
+    this.debugLog(DebugLogLevel.Verbose, 'Vitest config:', vitestConfig);
+    this.debugLog(DebugLogLevel.Verbose, 'Vitest server config:', vitestServerConfig);
+
+    return startVitest('test', undefined, vitestConfig, vitestServerConfig);
   }
 }
