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

This commit is contained in:
Pavel Feldman 2020-05-04 21:44:33 -07:00 committed by GitHub
parent 0bb1ba177c
commit 1c17929bd8
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
4 changed files with 44 additions and 25 deletions

View File

@ -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;

View File

@ -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));
}

View File

@ -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 {

View File

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