tests: print debugging info when timing out (#3190)

## Problem
It's not always clear why tests hang and timeout.

## Solution
Print pending UI elements before stopping the test. This is a more general solution over requiring tests to specify all responses up-front which is also viable.

Author: JadenSimon

src/test/globalSetup.test.ts

@@ -22,7 +22,7 @@ import { activateExtension } from '../shared/utilities/vsCodeUtils'
 import { FakeExtensionContext, FakeMemento } from './fakeExtensionContext'
 import { TestLogger } from './testLogger'
 import * as testUtil from './testUtil'
-import { getTestWindow, resetTestWindow } from './shared/vscode/window'
+import { printPendingUiElements, getTestWindow, resetTestWindow } from './shared/vscode/window'
 
 const testReportDir = join(__dirname, '../../../.test-reports')
 const testLogOutput = join(testReportDir, 'testLog.log')
@@ -80,14 +80,18 @@ beforeEach(async function () {
                         event.dispose()
                         reject(error)
                     })
+
+                    // Set a hard time limit per-test so CI doesn't hang
+                    // Mocha's `timeout` method isn't used because we want to emit a custom message
+                    setTimeout(() => {
+                        const message = `Test length exceeded max duration\n${printPendingUiElements()}`
+                        reject(new Error(message))
+                    }, maxTestDuration)
                 }),
             ])
         }
     }
 
-    // Set a hard time limit per-test so CI doesn't hang
-    this.currentTest?.timeout(maxTestDuration)
-
     // Enable telemetry features for tests. The metrics won't actually be posted.
     globals.telemetry.telemetryEnabled = true
     globals.telemetry.clearRecords()

src/test/shared/vscode/message.ts

@@ -58,7 +58,7 @@ export class TestMessage<T extends vscode.MessageItem = vscode.MessageItem> {
     }
 
     public get visible() {
-        return this._showing && this.message
+        return this._showing && !!this.message
     }
 
     public get detail() {
@@ -140,7 +140,11 @@ export class TestMessage<T extends vscode.MessageItem = vscode.MessageItem> {
     }
 
     public printDebug(message: string | RegExp = this.message, severity = this.severity) {
-        return `[${severity}]: ${typeof message === 'string' ? message : message.source}`
+        return [
+            `severity: ${severity}`,
+            `message: ${message}`,
+            `items: ${this.options?.items?.map(i => i.title).join(', ') || '[no items]'}`,
+        ].join(', ')
     }
 
     public dispose(): void {
@@ -166,7 +170,7 @@ export class TestMessage<T extends vscode.MessageItem = vscode.MessageItem> {
             throw new Error('Attempted to select from a disposed message')
         }
         if (!this.options?.items || this.options.items.length === 0) {
-            throw new Error(`Could not find the specified item: ${item}. Message has no items: ${this.message}`)
+            throw new Error(`Could not find the specified item "${item}". Message has no items: ${this.message}`)
         }
 
         const selected =
@@ -175,8 +179,7 @@ export class TestMessage<T extends vscode.MessageItem = vscode.MessageItem> {
                 : this.options?.items?.find(i => i === item)
 
         if (!selected) {
-            const items = this.options?.items?.map(i => i.title)?.join('\n')
-            throw new Error(`Could not find the specified item: ${item}. Current items:\n${items}`)
+            throw new Error(`Could not find the specified item "${item}" on message: ${this.printDebug()}`)
         }
 
         this._selected = selected
@@ -243,11 +246,11 @@ export class TestMessage<T extends vscode.MessageItem = vscode.MessageItem> {
 }
 
 interface OpenDialogOptions extends vscode.OpenDialogOptions {
-    readonly type: 'open'
+    readonly type: 'Open'
 }
 
 interface SaveDialogOptions extends vscode.SaveDialogOptions {
-    readonly type: 'save'
+    readonly type: 'Save'
 }
 
 type FileSystemDialogOptions = OpenDialogOptions | SaveDialogOptions
@@ -294,7 +297,7 @@ export class TestFileSystemDialog {
     }
 
     public get acceptButtonLabel() {
-        if (this.options.type === 'save') {
+        if (this.options.type === 'Save') {
             return this.options.saveLabel
         } else {
             return this.options.openLabel
@@ -343,12 +346,20 @@ export class TestFileSystemDialog {
         })
     }
 
+    public printDebug() {
+        return [
+            `type: ${this.options.type}`,
+            `title: ${this.title ?? '[no title]'}`,
+            `acceptButtonLabel: ${this.acceptButtonLabel ?? '[no label]'}`,
+        ].join(', ')
+    }
+
     public static createOpenSaveDialogFn(
         fs: vscode.FileSystem,
         callback?: (dialog: TestFileSystemDialog) => void
     ): Window['showOpenDialog'] {
         return async (options?: vscode.OpenDialogOptions) => {
-            const dialog = new TestFileSystemDialog([], { type: 'open', ...options })
+            const dialog = new TestFileSystemDialog([], { type: 'Open', ...options })
 
             return new Promise<vscode.Uri[] | undefined>(resolve => {
                 dialog.onDidAcceptItem(item => resolve(item instanceof vscode.Uri ? [item] : item))
@@ -363,7 +374,7 @@ export class TestFileSystemDialog {
         callback?: (dialog: TestFileSystemDialog) => void
     ): Window['showSaveDialog'] {
         return async (options?: vscode.SaveDialogOptions) => {
-            const dialog = new TestFileSystemDialog([], { type: 'save', ...options })
+            const dialog = new TestFileSystemDialog([], { type: 'Save', ...options })
 
             return new Promise<vscode.Uri | undefined>(resolve => {
                 dialog.onDidAcceptItem(item => resolve(Array.isArray(item) ? item[0] : item))

src/test/shared/vscode/window.ts

@@ -432,6 +432,24 @@ export function assertNoErrorMessages() {
     }
 }
 
+export function printPendingUiElements(window = getTestWindow()) {
+    const parts: string[] = []
+    const messages = window.shownMessages.filter(m => m.visible)
+    const dialogs = window.shownDialogs.filter(d => d.visible)
+
+    if (messages.length > 0) {
+        parts.push('Messages:', ...messages.map(m => `  ${m.printDebug()}`))
+    }
+    if (dialogs.length > 0) {
+        parts.push('File System Dialogs:', ...dialogs.map(d => `  ${d.printDebug()}`))
+    }
+    if (window.activeQuickInput?.visible) {
+        parts.push('Quick Inputs: ', `  ${window.activeQuickInput.title}`)
+    }
+
+    return parts.length > 0 ? ['Pending UI Elements:', ...parts].join('\n') : '[No Pending UI Elements Found]'
+}
+
 type TestEventEmitter<T> = vscode.EventEmitter<T> & {
     readonly onError: vscode.Event<{ event: T; error: unknown }>
 }