feat(debug): improve api logs (#2481)

This commit is contained in:
Dmitry Gozman 2020-06-06 20:59:06 -07:00 committed by GitHub
parent d5c55749d8
commit 5c3a275270
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
10 changed files with 127 additions and 84 deletions

View File

@ -246,10 +246,13 @@ export class ElementHandle<T extends Node = Node> extends js.JSHandle<T> {
}
async _retryPointerAction(progress: Progress, action: (point: types.Point) => Promise<void>, options: PointerActionOptions & types.PointerActionWaitOptions & types.NavigatingActionWaitOptions): Promise<void> {
let first = true;
while (progress.isRunning()) {
progress.log(apiLog, `${first ? 'attempting' : 'retrying'} ${progress.apiName} action`);
const result = await this._performPointerAction(progress, action, options);
if (result === 'done')
return;
first = false;
}
}
@ -258,27 +261,27 @@ export class ElementHandle<T extends Node = Node> extends js.JSHandle<T> {
if (!force)
await this._waitForDisplayedAtStablePositionAndEnabled(progress);
progress.log(apiLog, 'scrolling into view if needed...');
progress.log(apiLog, ' scrolling into view if needed');
const scrolled = await this._scrollRectIntoViewIfNeeded(position ? { x: position.x, y: position.y, width: 0, height: 0 } : undefined);
if (scrolled === 'invisible') {
if (force)
throw new Error('Element is not visible');
progress.log(apiLog, '...element is not visible, retrying input action');
progress.log(apiLog, ' element is not visible');
return 'retry';
}
progress.log(apiLog, '...done scrolling');
progress.log(apiLog, ' done scrolling');
const maybePoint = position ? await this._offsetPoint(position) : await this._clickablePoint();
if (maybePoint === 'invisible') {
if (force)
throw new Error('Element is not visible');
progress.log(apiLog, 'element is not visibile, retrying input action');
progress.log(apiLog, ' element is not visibile');
return 'retry';
}
if (maybePoint === 'outsideviewport') {
if (force)
throw new Error('Element is outside of the viewport');
progress.log(apiLog, 'element is outside of the viewport, retrying input action');
progress.log(apiLog, ' element is outside of the viewport');
return 'retry';
}
const point = roundPoint(maybePoint);
@ -286,29 +289,29 @@ export class ElementHandle<T extends Node = Node> extends js.JSHandle<T> {
if (!force) {
if ((options as any).__testHookBeforeHitTarget)
await (options as any).__testHookBeforeHitTarget();
progress.log(apiLog, `checking that element receives pointer events at (${point.x},${point.y})...`);
progress.log(apiLog, ` checking that element receives pointer events at (${point.x},${point.y})`);
const matchesHitTarget = await this._checkHitTargetAt(point);
if (!matchesHitTarget) {
progress.log(apiLog, '...element does not receive pointer events, retrying input action');
progress.log(apiLog, ' element does not receive pointer events');
return 'retry';
}
progress.log(apiLog, `...element does receive pointer events, continuing input action`);
progress.log(apiLog, ` element does receive pointer events, continuing input action`);
}
await this._page._frameManager.waitForSignalsCreatedBy(progress, options.noWaitAfter, async () => {
let restoreModifiers: input.Modifier[] | undefined;
if (options && options.modifiers)
restoreModifiers = await this._page.keyboard._ensureModifiers(options.modifiers);
progress.log(apiLog, `performing ${progress.apiName} action...`);
progress.log(apiLog, ` performing ${progress.apiName} action`);
await action(point);
progress.log(apiLog, `...${progress.apiName} action done`);
progress.log(apiLog, 'waiting for scheduled navigations to finish...');
progress.log(apiLog, ` ${progress.apiName} action done`);
progress.log(apiLog, ' waiting for scheduled navigations to finish');
if ((options as any).__testHookAfterPointerAction)
await (options as any).__testHookAfterPointerAction();
if (restoreModifiers)
await this._page.keyboard._ensureModifiers(restoreModifiers);
}, 'input');
progress.log(apiLog, '...navigations have finished');
progress.log(apiLog, ' navigations have finished');
return 'done';
}
@ -342,7 +345,6 @@ export class ElementHandle<T extends Node = Node> extends js.JSHandle<T> {
}
async _selectOption(progress: Progress, values: string | ElementHandle | types.SelectOption | string[] | ElementHandle[] | types.SelectOption[], options: types.NavigatingActionWaitOptions): Promise<string[]> {
progress.log(apiLog, progress.apiName);
let vals: string[] | ElementHandle[] | types.SelectOption[];
if (!Array.isArray(values))
vals = [ values ] as (string[] | ElementHandle[] | types.SelectOption[]);
@ -376,8 +378,8 @@ export class ElementHandle<T extends Node = Node> extends js.JSHandle<T> {
const poll = await this._evaluateHandleInUtility(([injected, node, value]) => {
return injected.waitForEnabledAndFill(node, value);
}, value);
new InjectedScriptPollHandler(progress, poll);
const injectedResult = await poll.evaluate(poll => poll.result);
const pollHandler = new InjectedScriptPollHandler(progress, poll);
const injectedResult = await pollHandler.finish();
const needsInput = handleInjectedResult(injectedResult);
if (needsInput) {
if (value)
@ -399,7 +401,6 @@ export class ElementHandle<T extends Node = Node> extends js.JSHandle<T> {
}
async _setInputFiles(progress: Progress, files: string | types.FilePayload | string[] | types.FilePayload[], options: types.NavigatingActionWaitOptions) {
progress.log(apiLog, progress.apiName);
const injectedResult = await this._evaluateInUtility(([injected, node]): types.InjectedScriptResult<boolean> => {
if (node.nodeType !== Node.ELEMENT_NODE || (node as Node as Element).tagName !== 'INPUT')
return { status: 'error', error: 'Node is not an HTMLInputElement' };
@ -522,15 +523,15 @@ export class ElementHandle<T extends Node = Node> extends js.JSHandle<T> {
}
async _waitForDisplayedAtStablePositionAndEnabled(progress: Progress): Promise<void> {
progress.log(apiLog, 'waiting for element to be displayed, enabled and not moving...');
progress.log(apiLog, ' waiting for element to be displayed, enabled and not moving');
const rafCount = this._page._delegate.rafCountForStablePosition();
const poll = await this._evaluateHandleInUtility(([injected, node, rafCount]) => {
return injected.waitForDisplayedAtStablePositionAndEnabled(node, rafCount);
}, rafCount);
new InjectedScriptPollHandler(progress, poll);
const injectedResult = await poll.evaluate(poll => poll.result);
const pollHandler = new InjectedScriptPollHandler<types.InjectedScriptResult>(progress, poll);
const injectedResult = await pollHandler.finish();
handleInjectedResult(injectedResult);
progress.log(apiLog, '...element is displayed and does not move');
progress.log(apiLog, ' element is displayed and does not move');
}
async _checkHitTargetAt(point: types.Point): Promise<boolean> {
@ -553,11 +554,11 @@ export class ElementHandle<T extends Node = Node> extends js.JSHandle<T> {
// Handles an InjectedScriptPoll running in injected script:
// - streams logs into progress;
// - cancels the poll when progress cancels.
export class InjectedScriptPollHandler {
export class InjectedScriptPollHandler<T> {
private _progress: Progress;
private _poll: js.JSHandle<types.InjectedScriptPoll<any>> | null;
private _poll: js.JSHandle<types.InjectedScriptPoll<T>> | null;
constructor(progress: Progress, poll: js.JSHandle<types.InjectedScriptPoll<any>>) {
constructor(progress: Progress, poll: js.JSHandle<types.InjectedScriptPoll<T>>) {
this._progress = progress;
this._poll = poll;
this._progress.cleanupWhenAborted(() => this.cancel());
@ -577,6 +578,35 @@ export class InjectedScriptPollHandler {
});
}
async finishHandle(): Promise<types.SmartHandle<T>> {
try {
const result = await this._poll!.evaluateHandle(poll => poll.result);
await this._finishInternal();
return result;
} finally {
this.cancel();
}
}
async finish(): Promise<T> {
try {
const result = await this._poll!.evaluate(poll => poll.result);
await this._finishInternal();
return result;
} finally {
this.cancel();
}
}
private async _finishInternal() {
if (!this._poll)
return;
// Retrieve all the logs before continuing.
const messages = await this._poll.evaluate(poll => poll.takeLastLogs()).catch(e => [] as string[]);
for (const message of messages)
this._progress.log(apiLog, message);
}
cancel() {
if (!this._poll)
return;

View File

@ -345,7 +345,7 @@ export class Frame {
const progressController = new ProgressController(this._page, this._page._timeoutSettings.navigationTimeout(options));
abortProgressOnFrameDetach(progressController, this);
return progressController.run(async progress => {
progress.log(apiLog, `${progress.apiName}("${url}"), waiting until "${options.waitUntil || 'load'}"`);
progress.log(apiLog, `navigating to "${url}", waiting until "${options.waitUntil || 'load'}"`);
const headers = (this._page._state.extraHTTPHeaders || {});
let referer = headers['referer'] || headers['Referer'];
if (options.referer !== undefined) {
@ -455,7 +455,7 @@ export class Frame {
throw new Error(`Unsupported waitFor option "${state}"`);
const { world, task } = selectors._waitForSelectorTask(selector, state);
return runAbortableTask(async progress => {
progress.log(apiLog, `Waiting for selector "${selector}"${state === 'attached' ? '' : ' to be ' + state}...`);
progress.log(apiLog, `waiting for selector "${selector}"${state === 'attached' ? '' : ' to be ' + state}`);
const result = await this._scheduleRerunnableTask(progress, world, task);
if (!result.asElement()) {
result.dispose();
@ -524,12 +524,11 @@ export class Frame {
abortProgressOnFrameDetach(progressController, this);
return progressController.run(async progress => {
const waitUntil = options.waitUntil === undefined ? 'load' : options.waitUntil;
progress.log(apiLog, `${progress.apiName}(), waiting until "${waitUntil}"`);
progress.log(apiLog, `setting frame content, waiting until "${waitUntil}"`);
const tag = `--playwright--set--content--${this._id}--${++this._setContentCounter}--`;
const context = await this._utilityContext();
const lifecyclePromise = new Promise((resolve, reject) => {
this._page._frameManager._consoleMessageTags.set(tag, () => {
progress.log(apiLog, 'content written');
// Clear lifecycle right after document.open() - see 'tag' below.
this._page._frameManager.clearFrameLifecycle(this);
this._waitForLoadState(progress, waitUntil).then(resolve).catch(reject);
@ -710,13 +709,11 @@ export class Frame {
selector: string, options: types.TimeoutOptions,
action: (progress: Progress, handle: dom.ElementHandle<Element>) => Promise<R>): Promise<R> {
return runAbortableTask(async progress => {
progress.log(apiLog, `${progress.apiName}("${selector}")`);
while (progress.isRunning()) {
try {
progress.log(apiLog, `waiting for selector "${selector}"`);
const { world, task } = selectors._waitForSelectorTask(selector, 'attached');
progress.log(apiLog, `waiting for the selector "${selector}"`);
const handle = await this._scheduleRerunnableTask(progress, world, task);
progress.log(apiLog, `...got element for the selector`);
const element = handle.asElement() as dom.ElementHandle<Element>;
progress.cleanupWhenAborted(() => element.dispose());
const result = await action(progress, element);
@ -915,16 +912,11 @@ class RerunnableTask<T> {
}
async rerun(context: dom.FrameExecutionContext) {
let pollHandler: dom.InjectedScriptPollHandler | null = null;
try {
const poll = await this._task(context);
pollHandler = new dom.InjectedScriptPollHandler(this._progress, poll);
const result = await poll.evaluateHandle(poll => poll.result);
const pollHandler = new dom.InjectedScriptPollHandler(this._progress, await this._task(context));
const result = await pollHandler.finishHandle();
this._resolve(result);
} catch (e) {
if (pollHandler)
pollHandler.cancel();
// When the page is navigated, the promise is rejected.
// We will try again in the new execution context.
if (e.message.includes('Execution context was destroyed'))

View File

@ -165,6 +165,7 @@ export default class InjectedScript {
logs,
result: poll(progress),
cancel: () => { progress.canceled = true; },
takeLastLogs: () => currentLogs,
};
}
@ -448,12 +449,34 @@ export default class InjectedScript {
}
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 attrs = [];
for (let i = 0; i < element.attributes.length; i++) {
if (element.attributes[i].name !== 'style')
attrs.push(` ${element.attributes[i].name}="${element.attributes[i].value}"`);
}
attrs.sort((a, b) => a.length - b.length);
let attrText = attrs.join('');
if (attrText.length > 50)
attrText = attrText.substring(0, 49) + '\u2026';
if (autoClosingTags.has(element.nodeName))
return `<${element.nodeName.toLowerCase()}${attrText}/>`;
const children = element.childNodes;
let onlyText = false;
if (children.length <= 5) {
onlyText = true;
for (let i = 0; i < children.length; i++)
onlyText = onlyText && children[i].nodeType === Node.TEXT_NODE;
}
let text = onlyText ? (element.textContent || '') : '';
if (text.length > 50)
text = text.substring(0, 49) + '\u2026';
return `<${element.nodeName.toLowerCase()}${attrText}>${text}</${element.nodeName.toLowerCase()}>`;
}
}
const autoClosingTags = new Set(['AREA', 'BASE', 'BR', 'COL', 'COMMAND', 'EMBED', 'HR', 'IMG', 'INPUT', 'KEYGEN', 'LINK', 'MENUITEM', 'META', 'PARAM', 'SOURCE', 'TRACK', 'WBR']);
const eventType = new Map<string, 'mouse'|'keyboard'|'touch'|'pointer'|'focus'|'drag'>([
['auxclick', 'mouse'],
['click', 'mouse'],

View File

@ -14,7 +14,7 @@
* limitations under the License.
*/
import { InnerLogger, Log } from './logger';
import { InnerLogger, Log, apiLog } from './logger';
import { TimeoutError } from './errors';
import { assert } from './helper';
import { getCurrentApiCall, rewriteErrorMessage } from './debug/stackTrace';
@ -82,11 +82,15 @@ export class ProgressController {
runCleanup(cleanup);
},
log: (log: Log, message: string | Error) => {
if (this._state === 'running')
if (this._state === 'running') {
this._logRecording.push(message.toString());
this._logger._log(log, ' ' + message);
} else {
this._logger._log(log, message);
}
},
};
this._logger._log(apiLog, `=> ${this._apiName} started`);
const timeoutError = new TimeoutError(`Timeout ${this._timeout}ms exceeded during ${this._apiName}.`);
const timer = setTimeout(() => this._forceAbort(timeoutError), progress.timeUntilDeadline());
@ -96,6 +100,7 @@ export class ProgressController {
clearTimeout(timer);
this._state = 'finished';
this._logRecording = [];
this._logger._log(apiLog, `<= ${this._apiName} succeeded`);
return result;
} catch (e) {
this._aborted();
@ -103,6 +108,7 @@ export class ProgressController {
clearTimeout(timer);
this._state = 'aborted';
this._logRecording = [];
this._logger._log(apiLog, `<= ${this._apiName} failed`);
await Promise.all(this._cleanups.splice(0).map(cleanup => runCleanup(cleanup)));
throw e;
}

View File

@ -120,38 +120,25 @@ export class Selectors {
return injected.poll('raf', (progress: types.InjectedScriptProgress) => {
const element = injected.querySelector(parsed, document);
const visible = element ? injected.isVisible(element) : false;
const log = (suffix: string) => {
if (lastElement === element)
return;
if (lastElement !== element) {
lastElement = element;
if (!element)
progress.log(` selector did not resolve to any element`);
else
progress.log(`selector resolved to "${injected.previewElement(element)}"${suffix ? ' ' + suffix : ''}`);
};
progress.log(` selector resolved to ${visible ? 'visible' : 'hidden'} ${injected.previewElement(element)}`);
}
switch (state) {
case 'attached': {
case 'attached':
return element || false;
}
case 'detached': {
if (element)
log('');
case 'detached':
return !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;
}
case 'visible':
return visible ? element : false;
case 'hidden':
return !visible;
}
});
}, { parsed, state });

View File

@ -176,6 +176,7 @@ export type InjectedScriptLogs = { current: string[], next: Promise<InjectedScri
export type InjectedScriptPoll<T> = {
result: Promise<T>,
logs: Promise<InjectedScriptLogs>,
takeLastLogs: () => string[],
cancel: () => void,
};

View File

@ -192,7 +192,7 @@ describe('Auto waiting', () => {
const __testHookAfterPointerAction = () => new Promise(f => setTimeout(f, 6000));
const error = await page.click('a', { timeout: 5000, __testHookAfterPointerAction }).catch(e => e);
expect(error.message).toContain('Timeout 5000ms exceeded during page.click.');
expect(error.message).toContain('waiting for scheduled navigations to finish...');
expect(error.message).toContain('waiting for scheduled navigations to finish');
expect(error.message).toContain(`navigated to "${server.PREFIX + '/frames/one-frame.html'}"`);
});
});

View File

@ -182,14 +182,14 @@ describe('Page.click', function() {
await page.$eval('button', b => b.style.display = 'none');
const error = await page.click('button', { timeout: 5000 }).catch(e => e);
expect(error.message).toContain('Timeout 5000ms exceeded during page.click.');
expect(error.message).toContain('waiting for element to be displayed, enabled and not moving...');
expect(error.message).toContain('waiting for element to be displayed, enabled and not moving');
});
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: 5000 }).catch(e => e);
expect(error.message).toContain('Timeout 5000ms exceeded during page.click.');
expect(error.message).toContain('waiting for element to be displayed, enabled and not moving...');
expect(error.message).toContain('waiting for element to be displayed, enabled and not moving');
});
it('should waitFor visible when parent is hidden', async({page, server}) => {
let done = false;
@ -431,7 +431,7 @@ describe('Page.click', function() {
});
const error = await button.click({ timeout: 5000 }).catch(e => e);
expect(error.message).toContain('Timeout 5000ms exceeded during elementHandle.click.');
expect(error.message).toContain('waiting for element to be displayed, enabled and not moving...');
expect(error.message).toContain('waiting for element to be displayed, enabled and not moving');
});
it('should wait for becoming hit target', async({page, server}) => {
await page.goto(server.PREFIX + '/input/button.html');
@ -479,7 +479,8 @@ describe('Page.click', function() {
});
const error = await button.click({ timeout: 5000 }).catch(e => e);
expect(error.message).toContain('Timeout 5000ms exceeded during elementHandle.click.');
expect(error.message).toContain('...element does not receive pointer events, retrying input action');
expect(error.message).toContain('element does not receive pointer events');
expect(error.message).toContain('retrying elementHandle.click action');
});
it('should fail when obscured and not waiting for hit target', async({page, server}) => {
await page.goto(server.PREFIX + '/input/button.html');
@ -704,7 +705,8 @@ describe('Page.click', function() {
expect(clicked).toBe(false);
expect(await page.evaluate(() => window.clicked)).toBe(undefined);
expect(error.message).toContain('Timeout 5000ms exceeded during elementHandle.click.');
expect(error.message).toContain('...element does not receive pointer events, retrying input action');
expect(error.message).toContain('element does not receive pointer events');
expect(error.message).toContain('retrying elementHandle.click action');
});
it('should dispatch microtasks in order', async({page, server}) => {
await page.setContent(`

View File

@ -919,7 +919,7 @@ describe('Frame.goto', function() {
const url = server.PREFIX + '/frames/child-redirect.html';
const error = await page.goto(url, { timeout: 5000, waitUntil: 'networkidle' }).catch(e => e);
expect(error.message).toContain('Timeout 5000ms exceeded during page.goto.');
expect(error.message).toContain(`page.goto("${url}"), waiting until "networkidle"`);
expect(error.message).toContain(`navigating to "${url}", waiting until "networkidle"`);
expect(error.message).toContain(`navigated to "${url}"`);
expect(error.message).toContain(`navigated to "${server.PREFIX + '/frames/one-frame.html'}"`);
expect(error.message).toContain(`"domcontentloaded" event fired`);

View File

@ -211,7 +211,9 @@ describe('Frame.waitForSelector', function() {
const div = document.createElement('div');
div.className = 'foo bar';
div.id = 'mydiv';
div.style.display = 'none';
div.setAttribute('style', 'display: none');
div.setAttribute('foo', '123456789012345678901234567890123456789012345678901234567890');
div.textContent = 'abcdefghijklmnopqrstuvwyxzabcdefghijklmnopqrstuvwyxzabcdefghijklmnopqrstuvwyxz';
document.body.appendChild(div);
});
await giveItTimeToLog(frame);
@ -229,10 +231,10 @@ describe('Frame.waitForSelector', function() {
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(`waiting for selector "div" to be visible`);
expect(error.message).toContain(`selector resolved to hidden <div id="mydiv" class="foo bar" foo="1234567890123456…>abcdefghijklmnopqrstuvwyxzabcdefghijklmnopqrstuvw…</div>`);
expect(error.message).toContain(`selector did not resolve to any element`);
expect(error.message).toContain(`selector resolved to "div.another" that is not visible`);
expect(error.message).toContain(`selector resolved to hidden <div class="another"></div>`);
});
it('should report logs while waiting for hidden', async({page, server}) => {
await page.goto(server.EMPTY_PAGE);
@ -259,9 +261,9 @@ describe('Frame.waitForSelector', function() {
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`);
expect(error.message).toContain(`waiting for selector "div" to be hidden`);
expect(error.message).toContain(`selector resolved to visible <div id="mydiv" class="foo bar">hello</div>`);
expect(error.message).toContain(`selector resolved to visible <div class="another">hello</div>`);
});
it('should resolve promise when node is added in shadow dom', async({page, server}) => {
await page.goto(server.EMPTY_PAGE);
@ -400,7 +402,7 @@ describe('Frame.waitForSelector', function() {
await page.waitForSelector('div', { timeout: 10, state: 'attached' }).catch(e => error = e);
expect(error).toBeTruthy();
expect(error.message).toContain('Timeout 10ms exceeded during page.waitForSelector');
expect(error.message).toContain('Waiting for selector "div"...');
expect(error.message).toContain('waiting for selector "div"');
expect(error).toBeInstanceOf(playwright.errors.TimeoutError);
});
it('should have an error message specifically for awaiting an element to be hidden', async({page, server}) => {
@ -409,7 +411,7 @@ describe('Frame.waitForSelector', function() {
await page.waitForSelector('div', { state: 'hidden', timeout: 1000 }).catch(e => error = e);
expect(error).toBeTruthy();
expect(error.message).toContain('Timeout 1000ms exceeded during page.waitForSelector');
expect(error.message).toContain('Waiting for selector "div" to be hidden...');
expect(error.message).toContain('waiting for selector "div" to be hidden');
});
it('should respond to node attribute mutation', async({page, server}) => {
let divFound = false;
@ -490,7 +492,7 @@ describe('Frame.waitForSelector xpath', function() {
await page.waitForSelector('//div', { state: 'attached', timeout: 10 }).catch(e => error = e);
expect(error).toBeTruthy();
expect(error.message).toContain('Timeout 10ms exceeded during page.waitForSelector');
expect(error.message).toContain('Waiting for selector "//div"...');
expect(error.message).toContain('waiting for selector "//div"');
expect(error).toBeInstanceOf(playwright.errors.TimeoutError);
});
it('should run in specified frame', async({page, server}) => {