chore: add input logging and timeout debugging hints (#2109)

Author: pavelfeldman

src/dom.ts

@@ -227,17 +227,18 @@ export class ElementHandle<T extends Node = Node> extends js.JSHandle<T> {
     return point;
   }
 
-  async _retryPointerAction(action: (point: types.Point) => Promise<void>, options: PointerActionOptions & types.PointerActionWaitOptions & types.NavigatingActionWaitOptions = {}): Promise<void> {
+  async _retryPointerAction(actionName: string, action: (point: types.Point) => Promise<void>, options: PointerActionOptions & types.PointerActionWaitOptions & types.NavigatingActionWaitOptions = {}): Promise<void> {
+    this._page._log(inputLog, `elementHandle.${actionName}()`);
     const deadline = this._page._timeoutSettings.computeDeadline(options);
     while (!helper.isPastDeadline(deadline)) {
-      const result = await this._performPointerAction(action, deadline, options);
+      const result = await this._performPointerAction(actionName, action, deadline, options);
       if (result === 'done')
         return;
     }
-    throw new TimeoutError(`waiting for element to receive pointer events failed: timeout exceeded`);
+    throw new TimeoutError(`waiting for element to receive pointer events failed: timeout exceeded. Re-run with the DEBUG=pw:input env variable to see the debug log.`);
   }
 
-  async _performPointerAction(action: (point: types.Point) => Promise<void>, deadline: number, options: PointerActionOptions & types.PointerActionWaitOptions & types.NavigatingActionWaitOptions = {}): Promise<'done' | 'retry'> {
+  async _performPointerAction(actionName: string, action: (point: types.Point) => Promise<void>, deadline: number, options: PointerActionOptions & types.PointerActionWaitOptions & types.NavigatingActionWaitOptions = {}): Promise<'done' | 'retry'> {
     const { force = false, position } = options;
     if (!force)
       await this._waitForDisplayedAtStablePosition(deadline);
@@ -271,10 +272,10 @@ export class ElementHandle<T extends Node = Node> extends js.JSHandle<T> {
         let restoreModifiers: input.Modifier[] | undefined;
         if (options && options.modifiers)
           restoreModifiers = await this._page.keyboard._ensureModifiers(options.modifiers);
-        this._page._log(inputLog, 'performing input action...');
+        this._page._log(inputLog, `performing "${actionName}" action...`);
         await action(point);
-        this._page._log(inputLog, '...input action done');
-        this._page._log(inputLog, 'waiting for navigations to finish...');
+        this._page._log(inputLog, `... "${actionName}" action done`);
+        this._page._log(inputLog, 'waiting for scheduled navigations to finish...');
         await this._page._delegate.setActivityPaused(false);
         paused = false;
         if (restoreModifiers)
@@ -290,18 +291,19 @@ export class ElementHandle<T extends Node = Node> extends js.JSHandle<T> {
   }
 
   hover(options?: PointerActionOptions & types.PointerActionWaitOptions): Promise<void> {
-    return this._retryPointerAction(point => this._page.mouse.move(point.x, point.y), options);
+    return this._retryPointerAction('hover', point => this._page.mouse.move(point.x, point.y), options);
   }
 
   click(options?: ClickOptions & types.PointerActionWaitOptions & types.NavigatingActionWaitOptions): Promise<void> {
-    return this._retryPointerAction(point => this._page.mouse.click(point.x, point.y, options), options);
+    return this._retryPointerAction('click', point => this._page.mouse.click(point.x, point.y, options), options);
   }
 
   dblclick(options?: MultiClickOptions & types.PointerActionWaitOptions & types.NavigatingActionWaitOptions): Promise<void> {
-    return this._retryPointerAction(point => this._page.mouse.dblclick(point.x, point.y, options), options);
+    return this._retryPointerAction('dblclick', point => this._page.mouse.dblclick(point.x, point.y, options), options);
   }
 
   async selectOption(values: string | ElementHandle | types.SelectOption | string[] | ElementHandle[] | types.SelectOption[], options?: types.NavigatingActionWaitOptions): Promise<string[]> {
+    this._page._log(inputLog, `elementHandle.selectOption(%s)`, values);
     const deadline = this._page._timeoutSettings.computeDeadline(options);
     let vals: string[] | ElementHandle[] | types.SelectOption[];
     if (!Array.isArray(values))
@@ -326,6 +328,7 @@ export class ElementHandle<T extends Node = Node> extends js.JSHandle<T> {
   }
 
   async fill(value: string, options?: types.NavigatingActionWaitOptions): Promise<void> {
+    this._page._log(inputLog, `elementHandle.fill(${value})`);
     assert(helper.isString(value), 'Value must be string. Found value "' + value + '" of type "' + (typeof value) + '"');
     const deadline = this._page._timeoutSettings.computeDeadline(options);
     await this._page._frameManager.waitForSignalsCreatedBy(async () => {
@@ -341,11 +344,13 @@ export class ElementHandle<T extends Node = Node> extends js.JSHandle<T> {
   }
 
   async selectText(): Promise<void> {
+    this._page._log(inputLog, `elementHandle.selectText()`);
     const injectedResult = await this._evaluateInUtility(({ injected, node }) => injected.selectText(node), {});
     handleInjectedResult(injectedResult, '');
   }
 
   async setInputFiles(files: string | types.FilePayload | string[] | types.FilePayload[], options?: types.NavigatingActionWaitOptions) {
+    this._page._log(inputLog, `elementHandle.setInputFiles(...)`);
     const deadline = this._page._timeoutSettings.computeDeadline(options);
     const injectedResult = await this._evaluateInUtility(({ node }): InjectedResult<boolean> => {
       if (node.nodeType !== Node.ELEMENT_NODE || (node as Node as Element).tagName !== 'INPUT')
@@ -381,11 +386,13 @@ export class ElementHandle<T extends Node = Node> extends js.JSHandle<T> {
   }
 
   async focus() {
+    this._page._log(inputLog, `elementHandle.focus()`);
     const injectedResult = await this._evaluateInUtility(({ injected, node }) => injected.focusNode(node), {});
     handleInjectedResult(injectedResult, '');
   }
 
   async type(text: string, options?: { delay?: number } & types.NavigatingActionWaitOptions) {
+    this._page._log(inputLog, `elementHandle.type("${text}")`);
     const deadline = this._page._timeoutSettings.computeDeadline(options);
     await this._page._frameManager.waitForSignalsCreatedBy(async () => {
       await this.focus();
@@ -394,6 +401,7 @@ export class ElementHandle<T extends Node = Node> extends js.JSHandle<T> {
   }
 
   async press(key: string, options?: { delay?: number } & types.NavigatingActionWaitOptions) {
+    this._page._log(inputLog, `elementHandle.press("${key}")`);
     const deadline = this._page._timeoutSettings.computeDeadline(options);
     await this._page._frameManager.waitForSignalsCreatedBy(async () => {
       await this.focus();
@@ -402,10 +410,12 @@ export class ElementHandle<T extends Node = Node> extends js.JSHandle<T> {
   }
 
   async check(options?: types.PointerActionWaitOptions & types.NavigatingActionWaitOptions) {
+    this._page._log(inputLog, `elementHandle.check()`);
     await this._setChecked(true, options);
   }
 
   async uncheck(options?: types.PointerActionWaitOptions & types.NavigatingActionWaitOptions) {
+    this._page._log(inputLog, `elementHandle.uncheck()`);
     await this._setChecked(false, options);
   }
 
@@ -494,7 +504,7 @@ function handleInjectedResult<T = undefined>(injectedResult: InjectedResult<T>,
   if (injectedResult.status === 'notconnected')
     throw new NotConnectedError();
   if (injectedResult.status === 'timeout')
-    throw new TimeoutError(`waiting for ${timeoutMessage} failed: timeout exceeded`);
+    throw new TimeoutError(`waiting for ${timeoutMessage} failed: timeout exceeded. Re-run with the DEBUG=pw:input env variable to see the debug log.`);
   if (injectedResult.status === 'error')
     throw new Error(injectedResult.error);
   return injectedResult.value as T;

src/frames.ts

@@ -684,13 +684,17 @@ export class Frame {
   }
 
   private async _retryWithSelectorIfNotConnected<R>(
+    actionName: string,
     selector: string, options: types.TimeoutOptions,
     action: (handle: dom.ElementHandle<Element>, deadline: number) => Promise<R>): Promise<R> {
     const deadline = this._page._timeoutSettings.computeDeadline(options);
+    this._page._log(dom.inputLog, `(page|frame).${actionName}("${selector}")`);
     while (!helper.isPastDeadline(deadline)) {
       try {
         const { world, task } = selectors._waitForSelectorTask(selector, 'attached', deadline);
+        this._page._log(dom.inputLog, `waiting for the selector "${selector}"`);
         const handle = await this._scheduleRerunnableTask(task, world, deadline, `selector "${selector}"`);
+        this._page._log(dom.inputLog, `...got element for the selector`);
         const element = handle.asElement() as dom.ElementHandle<Element>;
         try {
           return await action(element, deadline);
@@ -703,61 +707,61 @@ export class Frame {
         this._page._log(dom.inputLog, 'Element was detached from the DOM, retrying');
       }
     }
-    throw new TimeoutError(`waiting for selector "${selector}" failed: timeout exceeded`);
+    throw new TimeoutError(`waiting for selector "${selector}" failed: timeout exceeded. Re-run with the DEBUG=pw:input env variable to see the debug log.`);
   }
 
   async click(selector: string, options: dom.ClickOptions & types.PointerActionWaitOptions & types.NavigatingActionWaitOptions = {}) {
-    await this._retryWithSelectorIfNotConnected(selector, options,
+    await this._retryWithSelectorIfNotConnected('click', selector, options,
         (handle, deadline) => handle.click(helper.optionsWithUpdatedTimeout(options, deadline)));
   }
 
   async dblclick(selector: string, options: dom.MultiClickOptions & types.PointerActionWaitOptions & types.NavigatingActionWaitOptions = {}) {
-    await this._retryWithSelectorIfNotConnected(selector, options,
+    await this._retryWithSelectorIfNotConnected('dblclick', selector, options,
         (handle, deadline) => handle.dblclick(helper.optionsWithUpdatedTimeout(options, deadline)));
   }
 
   async fill(selector: string, value: string, options: types.NavigatingActionWaitOptions = {}) {
-    await this._retryWithSelectorIfNotConnected(selector, options,
+    await this._retryWithSelectorIfNotConnected('fill', selector, options,
         (handle, deadline) => handle.fill(value, helper.optionsWithUpdatedTimeout(options, deadline)));
   }
 
   async focus(selector: string, options: types.TimeoutOptions = {}) {
-    await this._retryWithSelectorIfNotConnected(selector, options,
+    await this._retryWithSelectorIfNotConnected('focus', selector, options,
         (handle, deadline) => handle.focus());
   }
 
   async hover(selector: string, options: dom.PointerActionOptions & types.PointerActionWaitOptions = {}) {
-    await this._retryWithSelectorIfNotConnected(selector, options,
+    await this._retryWithSelectorIfNotConnected('hover', selector, options,
         (handle, deadline) => handle.hover(helper.optionsWithUpdatedTimeout(options, deadline)));
   }
 
   async selectOption(selector: string, values: string | dom.ElementHandle | types.SelectOption | string[] | dom.ElementHandle[] | types.SelectOption[], options: types.NavigatingActionWaitOptions = {}): Promise<string[]> {
-    return await this._retryWithSelectorIfNotConnected(selector, options,
+    return await this._retryWithSelectorIfNotConnected('selectOption', selector, options,
         (handle, deadline) => handle.selectOption(values, helper.optionsWithUpdatedTimeout(options, deadline)));
   }
 
   async setInputFiles(selector: string, files: string | types.FilePayload | string[] | types.FilePayload[], options: types.NavigatingActionWaitOptions = {}): Promise<void> {
-    await this._retryWithSelectorIfNotConnected(selector, options,
+    await this._retryWithSelectorIfNotConnected('setInputFiles', selector, options,
         (handle, deadline) => handle.setInputFiles(files, helper.optionsWithUpdatedTimeout(options, deadline)));
   }
 
   async type(selector: string, text: string, options: { delay?: number } & types.NavigatingActionWaitOptions = {}) {
-    await this._retryWithSelectorIfNotConnected(selector, options,
+    await this._retryWithSelectorIfNotConnected('type', selector, options,
         (handle, deadline) => handle.type(text, helper.optionsWithUpdatedTimeout(options, deadline)));
   }
 
   async press(selector: string, key: string, options: { delay?: number } & types.NavigatingActionWaitOptions = {}) {
-    await this._retryWithSelectorIfNotConnected(selector, options,
+    await this._retryWithSelectorIfNotConnected('press', selector, options,
         (handle, deadline) => handle.press(key, helper.optionsWithUpdatedTimeout(options, deadline)));
   }
 
   async check(selector: string, options: types.PointerActionWaitOptions & types.NavigatingActionWaitOptions = {}) {
-    await this._retryWithSelectorIfNotConnected(selector, options,
+    await this._retryWithSelectorIfNotConnected('check', selector, options,
         (handle, deadline) => handle.check(helper.optionsWithUpdatedTimeout(options, deadline)));
   }
 
   async uncheck(selector: string, options: types.PointerActionWaitOptions & types.NavigatingActionWaitOptions = {}) {
-    await this._retryWithSelectorIfNotConnected(selector, options,
+    await this._retryWithSelectorIfNotConnected('uncheck', selector, options,
         (handle, deadline) => handle.uncheck(helper.optionsWithUpdatedTimeout(options, deadline)));
   }
 
@@ -879,7 +883,7 @@ class RerunnableTask {
     });
     // Since page navigation requires us to re-install the pageScript, we should track
     // timeout on our end.
-    const timeoutError = new TimeoutError(`waiting for ${title || 'function'} failed: timeout exceeded`);
+    const timeoutError = new TimeoutError(`waiting for ${title || 'function'} failed: timeout exceeded. Re-run with the DEBUG=pw:input env variable to see the debug log.`);
     this._timeoutTimer = setTimeout(() => this.terminate(timeoutError), helper.timeUntilDeadline(deadline));
   }
 

src/helper.ts

@@ -164,7 +164,7 @@ class Helper {
 
   static async waitWithDeadline<T>(promise: Promise<T>, taskName: string, deadline: number): Promise<T> {
     let reject: (error: Error) => void;
-    const timeoutError = new TimeoutError(`waiting for ${taskName} failed: timeout exceeded`);
+    const timeoutError = new TimeoutError(`Waiting for ${taskName} failed: timeout exceeded. Re-run with the DEBUG=pw:input env variable to see the debug log.`);
     const timeoutPromise = new Promise<T>((resolve, x) => reject = x);
     const timeoutTimer = setTimeout(() => reject(timeoutError), helper.timeUntilDeadline(deadline));
     try {

test/click.spec.js

@@ -183,12 +183,14 @@ describe('Page.click', function() {
     await page.$eval('button', b => b.style.display = 'none');
     const error = await page.click('button', { timeout: 100 }).catch(e => e);
     expect(error.message).toContain('timeout exceeded');
+    expect(error.message).toContain('DEBUG=pw:input');
   });
   it('should timeout waiting for visbility:hidden to be gone', async({page, server}) => {
     await page.goto(server.PREFIX + '/input/button.html');
     await page.$eval('button', b => b.style.visibility = 'hidden');
     const error = await page.click('button', { timeout: 100 }).catch(e => e);
     expect(error.message).toContain('timeout exceeded');
+    expect(error.message).toContain('DEBUG=pw:input');
   });
   it('should waitFor visible when parent is hidden', async({page, server}) => {
     let done = false;
@@ -433,6 +435,7 @@ describe('Page.click', function() {
     });
     const error = await button.click({ timeout: 100 }).catch(e => e);
     expect(error.message).toContain('timeout exceeded');
+    expect(error.message).toContain('DEBUG=pw:input');
   });
   it('should wait for becoming hit target', async({page, server}) => {
     await page.goto(server.PREFIX + '/input/button.html');
@@ -481,6 +484,7 @@ describe('Page.click', function() {
     });
     const error = await button.click({ timeout: 100 }).catch(e => e);
     expect(error.message).toContain('timeout exceeded');
+    expect(error.message).toContain('DEBUG=pw:input');
   });
   it('should fail when obscured and not waiting for hit target', async({page, server}) => {
     await page.goto(server.PREFIX + '/input/button.html');
@@ -583,6 +587,7 @@ describe('Page.click', function() {
     expect(clicked).toBe(false);
     expect(await page.evaluate(() => window.clicked)).toBe(undefined);
     expect(error.message).toContain('timeout exceeded');
+    expect(error.message).toContain('DEBUG=pw:input');
   });
   it.skip(true)('should pause animations', async({page}) => {
     // This test requires pausing the page.