diff --git a/src/dom.ts b/src/dom.ts index fa36e8b094..31c13c7e32 100644 --- a/src/dom.ts +++ b/src/dom.ts @@ -227,17 +227,18 @@ export class ElementHandle extends js.JSHandle { return point; } - async _retryPointerAction(action: (point: types.Point) => Promise, options: PointerActionOptions & types.PointerActionWaitOptions & types.NavigatingActionWaitOptions = {}): Promise { + async _retryPointerAction(actionName: string, action: (point: types.Point) => Promise, options: PointerActionOptions & types.PointerActionWaitOptions & types.NavigatingActionWaitOptions = {}): Promise { + 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, deadline: number, options: PointerActionOptions & types.PointerActionWaitOptions & types.NavigatingActionWaitOptions = {}): Promise<'done' | 'retry'> { + async _performPointerAction(actionName: string, action: (point: types.Point) => Promise, 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 extends js.JSHandle { 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 extends js.JSHandle { } hover(options?: PointerActionOptions & types.PointerActionWaitOptions): Promise { - 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 { - 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 { - 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 { + 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 extends js.JSHandle { } async fill(value: string, options?: types.NavigatingActionWaitOptions): Promise { + 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 extends js.JSHandle { } async selectText(): Promise { + 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 => { if (node.nodeType !== Node.ELEMENT_NODE || (node as Node as Element).tagName !== 'INPUT') @@ -381,11 +386,13 @@ export class ElementHandle extends js.JSHandle { } 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 extends js.JSHandle { } 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 extends js.JSHandle { } 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(injectedResult: InjectedResult, 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; diff --git a/src/frames.ts b/src/frames.ts index 9d4b4343b4..dbbace39d4 100644 --- a/src/frames.ts +++ b/src/frames.ts @@ -684,13 +684,17 @@ export class Frame { } private async _retryWithSelectorIfNotConnected( + actionName: string, selector: string, options: types.TimeoutOptions, action: (handle: dom.ElementHandle, deadline: number) => Promise): Promise { 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; 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 { - 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 { - 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)); } diff --git a/src/helper.ts b/src/helper.ts index c2d864fa1b..43b7825da6 100644 --- a/src/helper.ts +++ b/src/helper.ts @@ -164,7 +164,7 @@ class Helper { static async waitWithDeadline(promise: Promise, taskName: string, deadline: number): Promise { 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((resolve, x) => reject = x); const timeoutTimer = setTimeout(() => reject(timeoutError), helper.timeUntilDeadline(deadline)); try { diff --git a/test/click.spec.js b/test/click.spec.js index 3a168b2ba3..464540f2b3 100644 --- a/test/click.spec.js +++ b/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.