From bf67245de6a480ecfd4f37bafc8f3036ff1fb832 Mon Sep 17 00:00:00 2001 From: Dmitry Gozman Date: Mon, 1 Jun 2020 15:48:23 -0700 Subject: [PATCH] feat(debug): stream logs from waitForSelector (#2434) - we can now stream logs from InjectedScriptProgress to Progress; - waitForSelector task uses it to report intermediate elements. --- src/dom.ts | 37 +++++++++ src/frames.ts | 24 ++---- src/injected/injectedScript.ts | 137 ++++++++++++++++++++------------- src/progress.ts | 4 + src/selectors.ts | 39 ++++++++-- src/types.ts | 9 ++- test/waittask.spec.js | 66 ++++++++++++++++ 7 files changed, 237 insertions(+), 79 deletions(-) diff --git a/src/dom.ts b/src/dom.ts index cea19877d0..f49e228a7c 100644 --- a/src/dom.ts +++ b/src/dom.ts @@ -29,6 +29,7 @@ import { selectors } from './selectors'; import * as types from './types'; import { NotConnectedError, TimeoutError } from './errors'; import { Log, logError } from './logger'; +import { Progress } from './progress'; export type PointerActionOptions = { modifiers?: input.Modifier[]; @@ -514,6 +515,42 @@ export class ElementHandle extends js.JSHandle { } } +// Handles an InjectedScriptPoll running in injected script: +// - streams logs into progress; +// - cancels the poll when progress cancels. +export class InjectedScriptPollHandler { + private _progress: Progress; + private _poll: js.JSHandle> | null; + + constructor(progress: Progress, poll: js.JSHandle>) { + this._progress = progress; + this._poll = poll; + this._progress.cleanupWhenCanceled(() => this.cancel()); + this._streamLogs(poll.evaluateHandle(poll => poll.logs)); + } + + private _streamLogs(logsPromise: Promise>) { + // We continuously get a chunk of logs, stream them to the progress and wait for the next chunk. + logsPromise.catch(e => null).then(logs => { + if (!logs || !this._poll || this._progress.isCanceled()) + return; + logs.evaluate(logs => logs.current).catch(e => [] as string[]).then(messages => { + for (const message of messages) + this._progress.log(inputLog, message); + }); + this._streamLogs(logs.evaluateHandle(logs => logs.next)); + }); + } + + cancel() { + if (!this._poll) + return; + const copy = this._poll; + this._poll = null; + copy.evaluate(p => p.cancel()).catch(e => {}).then(() => copy.dispose()); + } +} + export function toFileTransferPayload(files: types.FilePayload[]): types.FileTransferPayload[] { return files.map(file => ({ name: file.name, diff --git a/src/frames.ts b/src/frames.ts index 1054d9fce5..04fd1c87c8 100644 --- a/src/frames.ts +++ b/src/frames.ts @@ -898,7 +898,7 @@ export class Frame { } } -export type SchedulableTask = (context: dom.FrameExecutionContext) => Promise>>; +export type SchedulableTask = (context: dom.FrameExecutionContext) => Promise>>; class RerunnableTask { readonly promise: Promise>; @@ -919,29 +919,19 @@ class RerunnableTask { } terminate(error: Error) { - this._progress.cancel(error); + this._reject(error); } async rerun(context: dom.FrameExecutionContext) { - let poll: js.JSHandle> | null = null; - - // On timeout or error, cancel current poll. - const cancelPoll = () => { - if (!poll) - return; - const copy = poll; - poll = null; - copy.evaluate(p => p.cancel()).catch(e => {}).then(() => copy.dispose()); - }; - this._progress.cleanupWhenCanceled(cancelPoll); - + let pollHandler: dom.InjectedScriptPollHandler | null = null; try { - poll = await this._task(context); + const poll = await this._task(context); + pollHandler = new dom.InjectedScriptPollHandler(this._progress, poll); const result = await poll.evaluateHandle(poll => poll.result); - cancelPoll(); this._resolve(result); } catch (e) { - cancelPoll(); + if (pollHandler) + pollHandler.cancel(); // When the page is navigated, the promise is rejected. // We will try again in the new execution context. diff --git a/src/injected/injectedScript.ts b/src/injected/injectedScript.ts index 5d316340f0..67a1c3211e 100644 --- a/src/injected/injectedScript.ts +++ b/src/injected/injectedScript.ts @@ -22,14 +22,7 @@ import { createTextSelector } from './textSelectorEngine'; import { XPathEngine } from './xpathSelectorEngine'; type Falsy = false | 0 | '' | undefined | null; -type Predicate = () => T | Falsy; -type InjectedScriptProgress = { - canceled: boolean; -}; - -function asCancelablePoll(result: T): types.CancelablePoll { - return { result: Promise.resolve(result), cancel: () => {} }; -} +type Predicate = (progress: types.InjectedScriptProgress) => T | Falsy; export default class InjectedScript { readonly engines: Map; @@ -111,14 +104,14 @@ export default class InjectedScript { return rect.width > 0 && rect.height > 0; } - private _pollRaf(progress: InjectedScriptProgress, predicate: Predicate): Promise { + private _pollRaf(progress: types.InjectedScriptProgress, predicate: Predicate): Promise { let fulfill: (result: T) => void; const result = new Promise(x => fulfill = x); const onRaf = () => { if (progress.canceled) return; - const success = predicate(); + const success = predicate(progress); if (success) fulfill(success); else @@ -129,13 +122,13 @@ export default class InjectedScript { return result; } - private _pollInterval(progress: InjectedScriptProgress, pollInterval: number, predicate: Predicate): Promise { + private _pollInterval(progress: types.InjectedScriptProgress, pollInterval: number, predicate: Predicate): Promise { let fulfill: (result: T) => void; const result = new Promise(x => fulfill = x); const onTimeout = () => { if (progress.canceled) return; - const success = predicate(); + const success = predicate(progress); if (success) fulfill(success); else @@ -146,11 +139,39 @@ export default class InjectedScript { return result; } - poll(polling: 'raf' | number, predicate: Predicate): types.CancelablePoll { - const progress = { canceled: false }; - const cancel = () => { progress.canceled = true; }; - const result = polling === 'raf' ? this._pollRaf(progress, predicate) : this._pollInterval(progress, polling, predicate); - return { result, cancel }; + private _runCancellablePoll(poll: (progess: types.InjectedScriptProgress) => Promise): types.InjectedScriptPoll { + let currentLogs: string[] = []; + let logReady = () => {}; + const createLogsPromise = () => new Promise(fulfill => { + logReady = () => { + const current = currentLogs; + currentLogs = []; + fulfill({ current, next: createLogsPromise() }); + }; + }); + + const progress: types.InjectedScriptProgress = { + canceled: false, + log: (message: string) => { + currentLogs.push(message); + logReady(); + }, + }; + + // It is important to create logs promise before running the poll to capture logs from the first run. + const logs = createLogsPromise(); + + return { + logs, + result: poll(progress), + cancel: () => { progress.canceled = true; }, + }; + } + + poll(polling: 'raf' | number, predicate: Predicate): types.InjectedScriptPoll { + return this._runCancellablePoll(progress => { + return polling === 'raf' ? this._pollRaf(progress, predicate) : this._pollInterval(progress, polling, predicate); + }); } getElementBorderWidth(node: Node): { left: number; top: number; } { @@ -327,50 +348,52 @@ export default class InjectedScript { input.dispatchEvent(new Event('change', { 'bubbles': true })); } - waitForDisplayedAtStablePositionAndEnabled(node: Node, rafCount: number): types.CancelablePoll { - if (!node.isConnected) - return asCancelablePoll({ status: 'notconnected' }); - const element = node.nodeType === Node.ELEMENT_NODE ? (node as Element) : node.parentElement; - if (!element) - return asCancelablePoll({ status: 'notconnected' }); - - let lastRect: types.Rect | undefined; - let counter = 0; - let samePositionCounter = 0; - let lastTime = 0; - return this.poll('raf', (): types.InjectedScriptResult | false => { - // First raf happens in the same animation frame as evaluation, so it does not produce - // any client rect difference compared to synchronous call. We skip the synchronous call - // and only force layout during actual rafs as a small optimisation. - if (++counter === 1) - return false; + waitForDisplayedAtStablePositionAndEnabled(node: Node, rafCount: number): types.InjectedScriptPoll { + return this._runCancellablePoll(async progress => { if (!node.isConnected) return { status: 'notconnected' }; + const element = node.nodeType === Node.ELEMENT_NODE ? (node as Element) : node.parentElement; + if (!element) + return { status: 'notconnected' }; - // Drop frames that are shorter than 16ms - WebKit Win bug. - const time = performance.now(); - if (rafCount > 1 && time - lastTime < 15) - return false; - lastTime = time; + let lastRect: types.Rect | undefined; + let counter = 0; + let samePositionCounter = 0; + let lastTime = 0; + return this._pollRaf(progress, (): types.InjectedScriptResult | false => { + // First raf happens in the same animation frame as evaluation, so it does not produce + // any client rect difference compared to synchronous call. We skip the synchronous call + // and only force layout during actual rafs as a small optimisation. + if (++counter === 1) + return false; + if (!node.isConnected) + return { status: 'notconnected' }; - // Note: this logic should be similar to isVisible() to avoid surprises. - const clientRect = element.getBoundingClientRect(); - const rect = { x: clientRect.top, y: clientRect.left, width: clientRect.width, height: clientRect.height }; - const samePosition = lastRect && rect.x === lastRect.x && rect.y === lastRect.y && rect.width === lastRect.width && rect.height === lastRect.height && rect.width > 0 && rect.height > 0; - lastRect = rect; - if (samePosition) - ++samePositionCounter; - else - samePositionCounter = 0; - const isDisplayedAndStable = samePositionCounter >= rafCount; + // Drop frames that are shorter than 16ms - WebKit Win bug. + const time = performance.now(); + if (rafCount > 1 && time - lastTime < 15) + return false; + lastTime = time; - const style = element.ownerDocument && element.ownerDocument.defaultView ? element.ownerDocument.defaultView.getComputedStyle(element) : undefined; - const isVisible = !!style && style.visibility !== 'hidden'; + // Note: this logic should be similar to isVisible() to avoid surprises. + const clientRect = element.getBoundingClientRect(); + const rect = { x: clientRect.top, y: clientRect.left, width: clientRect.width, height: clientRect.height }; + const samePosition = lastRect && rect.x === lastRect.x && rect.y === lastRect.y && rect.width === lastRect.width && rect.height === lastRect.height && rect.width > 0 && rect.height > 0; + lastRect = rect; + if (samePosition) + ++samePositionCounter; + else + samePositionCounter = 0; + const isDisplayedAndStable = samePositionCounter >= rafCount; - const elementOrButton = element.closest('button, [role=button]') || element; - const isDisabled = ['BUTTON', 'INPUT', 'SELECT'].includes(elementOrButton.nodeName) && elementOrButton.hasAttribute('disabled'); + const style = element.ownerDocument && element.ownerDocument.defaultView ? element.ownerDocument.defaultView.getComputedStyle(element) : undefined; + const isVisible = !!style && style.visibility !== 'hidden'; - return isDisplayedAndStable && isVisible && !isDisabled ? { status: 'success' } : false; + const elementOrButton = element.closest('button, [role=button]') || element; + const isDisabled = ['BUTTON', 'INPUT', 'SELECT'].includes(elementOrButton.nodeName) && elementOrButton.hasAttribute('disabled'); + + return isDisplayedAndStable && isVisible && !isDisabled ? { status: 'success' } : false; + }); }); } @@ -421,6 +444,12 @@ export default class InjectedScript { } return element; } + + previewElement(element: Element): string { + const id = element.id ? '#' + element.id : ''; + const classes = Array.from(element.classList).map(c => '.' + c).join(''); + return `${element.nodeName.toLowerCase()}${id}${classes}`; + } } const eventType = new Map([ diff --git a/src/progress.ts b/src/progress.ts index 259202b68d..2a07eaa482 100644 --- a/src/progress.ts +++ b/src/progress.ts @@ -74,6 +74,10 @@ export class Progress { this._logger = logger; } + isCanceled(): boolean { + return !this._running; + } + cleanupWhenCanceled(cleanup: () => any) { if (this._running) this._cleanups.push(cleanup); diff --git a/src/selectors.ts b/src/selectors.ts index 0c6d60ea65..2c4b8a14f0 100644 --- a/src/selectors.ts +++ b/src/selectors.ts @@ -116,17 +116,42 @@ export class Selectors { const task = async (context: dom.FrameExecutionContext) => { const injectedScript = await context.injectedScript(); return injectedScript.evaluateHandle((injected, { parsed, state }) => { - return injected.poll('raf', () => { + let lastElement: Element | undefined; + + return injected.poll('raf', (progress: types.InjectedScriptProgress) => { const element = injected.querySelector(parsed, document); + + const log = (suffix: string) => { + if (lastElement === element) + return; + lastElement = element; + if (!element) + progress.log(`selector did not resolve to any element`); + else + progress.log(`selector resolved to "${injected.previewElement(element)}"${suffix ? ' ' + suffix : ''}`); + }; + switch (state) { - case 'attached': + case 'attached': { return element || false; - case 'detached': + } + case 'detached': { + if (element) + log(''); return !element; - case 'visible': - return element && injected.isVisible(element) ? element : false; - case 'hidden': - return !element || !injected.isVisible(element); + } + case 'visible': { + const result = element && injected.isVisible(element) ? element : false; + if (!result) + log('that is not visible'); + return result; + } + case 'hidden': { + const result = !element || !injected.isVisible(element); + if (!result) + log('that is still visible'); + return result; + } } }); }, { parsed, state }); diff --git a/src/types.ts b/src/types.ts index 60b7ead6a9..dd2a0f17a8 100644 --- a/src/types.ts +++ b/src/types.ts @@ -169,7 +169,14 @@ export type InjectedScriptResult = { status: 'notconnected' } | { status: 'error', error: string }; -export type CancelablePoll = { +export type InjectedScriptProgress = { + canceled: boolean, + log: (message: string) => void, +}; + +export type InjectedScriptLogs = { current: string[], next: Promise }; +export type InjectedScriptPoll = { result: Promise, + logs: Promise, cancel: () => void, }; diff --git a/test/waittask.spec.js b/test/waittask.spec.js index 0d5979405b..e2de76b273 100644 --- a/test/waittask.spec.js +++ b/test/waittask.spec.js @@ -18,6 +18,11 @@ const utils = require('./utils'); const {FFOX, CHROMIUM, WEBKIT} = utils.testOptions(browserType); +async function giveItTimeToLog(frame) { + await frame.evaluate(() => new Promise(f => requestAnimationFrame(() => requestAnimationFrame(f)))); + await frame.evaluate(() => new Promise(f => requestAnimationFrame(() => requestAnimationFrame(f)))); +} + describe('Page.waitForTimeout', function() { it('should timeout', async({page, server}) => { const startTime = Date.now(); @@ -197,6 +202,67 @@ describe('Frame.waitForSelector', function() { const tagName = await eHandle.getProperty('tagName').then(e => e.jsonValue()); expect(tagName).toBe('DIV'); }); + it('should report logs while waiting for visible', async({page, server}) => { + await page.goto(server.EMPTY_PAGE); + const frame = page.mainFrame(); + const watchdog = frame.waitForSelector('div', { timeout: 5000 }); + + await frame.evaluate(() => { + const div = document.createElement('div'); + div.className = 'foo bar'; + div.id = 'mydiv'; + div.style.display = 'none'; + document.body.appendChild(div); + }); + await giveItTimeToLog(frame); + + await frame.evaluate(() => document.querySelector('div').remove()); + await giveItTimeToLog(frame); + + await frame.evaluate(() => { + const div = document.createElement('div'); + div.className = 'another'; + div.style.display = 'none'; + document.body.appendChild(div); + }); + await giveItTimeToLog(frame); + + const error = await watchdog.catch(e => e); + expect(error.message).toContain(`Timeout 5000ms exceeded during frame.waitForSelector.`); + expect(error.message).toContain(`Waiting for selector "div" to be visible...`); + expect(error.message).toContain(`selector resolved to "div#mydiv.foo.bar" that is not visible`); + expect(error.message).toContain(`selector did not resolve to any element`); + expect(error.message).toContain(`selector resolved to "div.another" that is not visible`); + }); + it('should report logs while waiting for hidden', async({page, server}) => { + await page.goto(server.EMPTY_PAGE); + const frame = page.mainFrame(); + await frame.evaluate(() => { + const div = document.createElement('div'); + div.className = 'foo bar'; + div.id = 'mydiv'; + div.textContent = 'hello'; + document.body.appendChild(div); + }); + + const watchdog = frame.waitForSelector('div', { state: 'hidden', timeout: 5000 }); + await giveItTimeToLog(frame); + + await frame.evaluate(() => { + document.querySelector('div').remove(); + const div = document.createElement('div'); + div.className = 'another'; + div.textContent = 'hello'; + document.body.appendChild(div); + }); + await giveItTimeToLog(frame); + + const error = await watchdog.catch(e => e); + expect(error.message).toContain(`Timeout 5000ms exceeded during frame.waitForSelector.`); + expect(error.message).toContain(`Waiting for selector "div" to be hidden...`); + expect(error.message).toContain(`selector resolved to "div#mydiv.foo.bar" that is still visible`); + expect(error.message).toContain(`selector resolved to "div.another" that is still visible`); + }); it('should resolve promise when node is added in shadow dom', async({page, server}) => { await page.goto(server.EMPTY_PAGE); const watchdog = page.waitForSelector('span');