Skip to content

Commit 5c3a275

Browse files
dgozmandgozman
authored
feat(debug): improve api logs (#2481)
1 parent d5c5574 commit 5c3a275

File tree

10 files changed

+127
-84
lines changed

10 files changed

+127
-84
lines changed

‎src/dom.ts

Lines changed: 53 additions & 23 deletions
Original file line numberDiff line numberDiff line change
@@ -246,10 +246,13 @@ export class ElementHandle<T extends Node = Node> extends js.JSHandle<T> {
246246
}
247247

248248
async _retryPointerAction(progress: Progress, action: (point: types.Point) => Promise<void>, options: PointerActionOptions & types.PointerActionWaitOptions & types.NavigatingActionWaitOptions): Promise<void> {
249+
let first = true;
249250
while (progress.isRunning()) {
251+
progress.log(apiLog, `${first ? 'attempting' : 'retrying'} ${progress.apiName} action`);
250252
const result = await this._performPointerAction(progress, action, options);
251253
if (result === 'done')
252254
return;
255+
first = false;
253256
}
254257
}
255258

@@ -258,57 +261,57 @@ export class ElementHandle<T extends Node = Node> extends js.JSHandle<T> {
258261
if (!force)
259262
await this._waitForDisplayedAtStablePositionAndEnabled(progress);
260263

261-
progress.log(apiLog, 'scrolling into view if needed...');
264+
progress.log(apiLog, ' scrolling into view if needed');
262265
const scrolled = await this._scrollRectIntoViewIfNeeded(position ? { x: position.x, y: position.y, width: 0, height: 0 } : undefined);
263266
if (scrolled === 'invisible') {
264267
if (force)
265268
throw new Error('Element is not visible');
266-
progress.log(apiLog, '...element is not visible, retrying input action');
269+
progress.log(apiLog, ' element is not visible');
267270
return 'retry';
268271
}
269-
progress.log(apiLog, '...done scrolling');
272+
progress.log(apiLog, ' done scrolling');
270273

271274
const maybePoint = position ? await this._offsetPoint(position) : await this._clickablePoint();
272275
if (maybePoint === 'invisible') {
273276
if (force)
274277
throw new Error('Element is not visible');
275-
progress.log(apiLog, 'element is not visibile, retrying input action');
278+
progress.log(apiLog, ' element is not visibile');
276279
return 'retry';
277280
}
278281
if (maybePoint === 'outsideviewport') {
279282
if (force)
280283
throw new Error('Element is outside of the viewport');
281-
progress.log(apiLog, 'element is outside of the viewport, retrying input action');
284+
progress.log(apiLog, ' element is outside of the viewport');
282285
return 'retry';
283286
}
284287
const point = roundPoint(maybePoint);
285288

286289
if (!force) {
287290
if ((options as any).__testHookBeforeHitTarget)
288291
await (options as any).__testHookBeforeHitTarget();
289-
progress.log(apiLog, `checking that element receives pointer events at (${point.x},${point.y})...`);
292+
progress.log(apiLog, ` checking that element receives pointer events at (${point.x},${point.y})`);
290293
const matchesHitTarget = await this._checkHitTargetAt(point);
291294
if (!matchesHitTarget) {
292-
progress.log(apiLog, '...element does not receive pointer events, retrying input action');
295+
progress.log(apiLog, ' element does not receive pointer events');
293296
return 'retry';
294297
}
295-
progress.log(apiLog, `...element does receive pointer events, continuing input action`);
298+
progress.log(apiLog, ` element does receive pointer events, continuing input action`);
296299
}
297300

298301
await this._page._frameManager.waitForSignalsCreatedBy(progress, options.noWaitAfter, async () => {
299302
let restoreModifiers: input.Modifier[] | undefined;
300303
if (options && options.modifiers)
301304
restoreModifiers = await this._page.keyboard._ensureModifiers(options.modifiers);
302-
progress.log(apiLog, `performing ${progress.apiName} action...`);
305+
progress.log(apiLog, ` performing ${progress.apiName} action`);
303306
await action(point);
304-
progress.log(apiLog, `...${progress.apiName} action done`);
305-
progress.log(apiLog, 'waiting for scheduled navigations to finish...');
307+
progress.log(apiLog, ` ${progress.apiName} action done`);
308+
progress.log(apiLog, ' waiting for scheduled navigations to finish');
306309
if ((options as any).__testHookAfterPointerAction)
307310
await (options as any).__testHookAfterPointerAction();
308311
if (restoreModifiers)
309312
await this._page.keyboard._ensureModifiers(restoreModifiers);
310313
}, 'input');
311-
progress.log(apiLog, '...navigations have finished');
314+
progress.log(apiLog, ' navigations have finished');
312315

313316
return 'done';
314317
}
@@ -342,7 +345,6 @@ export class ElementHandle<T extends Node = Node> extends js.JSHandle<T> {
342345
}
343346

344347
async _selectOption(progress: Progress, values: string | ElementHandle | types.SelectOption | string[] | ElementHandle[] | types.SelectOption[], options: types.NavigatingActionWaitOptions): Promise<string[]> {
345-
progress.log(apiLog, progress.apiName);
346348
let vals: string[] | ElementHandle[] | types.SelectOption[];
347349
if (!Array.isArray(values))
348350
vals = [ values ] as (string[] | ElementHandle[] | types.SelectOption[]);
@@ -376,8 +378,8 @@ export class ElementHandle<T extends Node = Node> extends js.JSHandle<T> {
376378
const poll = await this._evaluateHandleInUtility(([injected, node, value]) => {
377379
return injected.waitForEnabledAndFill(node, value);
378380
}, value);
379-
new InjectedScriptPollHandler(progress, poll);
380-
const injectedResult = await poll.evaluate(poll => poll.result);
381+
const pollHandler = new InjectedScriptPollHandler(progress, poll);
382+
const injectedResult = await pollHandler.finish();
381383
const needsInput = handleInjectedResult(injectedResult);
382384
if (needsInput) {
383385
if (value)
@@ -399,7 +401,6 @@ export class ElementHandle<T extends Node = Node> extends js.JSHandle<T> {
399401
}
400402

401403
async _setInputFiles(progress: Progress, files: string | types.FilePayload | string[] | types.FilePayload[], options: types.NavigatingActionWaitOptions) {
402-
progress.log(apiLog, progress.apiName);
403404
const injectedResult = await this._evaluateInUtility(([injected, node]): types.InjectedScriptResult<boolean> => {
404405
if (node.nodeType !== Node.ELEMENT_NODE || (node as Node as Element).tagName !== 'INPUT')
405406
return { status: 'error', error: 'Node is not an HTMLInputElement' };
@@ -522,15 +523,15 @@ export class ElementHandle<T extends Node = Node> extends js.JSHandle<T> {
522523
}
523524

524525
async _waitForDisplayedAtStablePositionAndEnabled(progress: Progress): Promise<void> {
525-
progress.log(apiLog, 'waiting for element to be displayed, enabled and not moving...');
526+
progress.log(apiLog, ' waiting for element to be displayed, enabled and not moving');
526527
const rafCount = this._page._delegate.rafCountForStablePosition();
527528
const poll = await this._evaluateHandleInUtility(([injected, node, rafCount]) => {
528529
return injected.waitForDisplayedAtStablePositionAndEnabled(node, rafCount);
529530
}, rafCount);
530-
new InjectedScriptPollHandler(progress, poll);
531-
const injectedResult = await poll.evaluate(poll => poll.result);
531+
const pollHandler = new InjectedScriptPollHandler<types.InjectedScriptResult>(progress, poll);
532+
const injectedResult = await pollHandler.finish();
532533
handleInjectedResult(injectedResult);
533-
progress.log(apiLog, '...element is displayed and does not move');
534+
progress.log(apiLog, ' element is displayed and does not move');
534535
}
535536

536537
async _checkHitTargetAt(point: types.Point): Promise<boolean> {
@@ -553,11 +554,11 @@ export class ElementHandle<T extends Node = Node> extends js.JSHandle<T> {
553554
// Handles an InjectedScriptPoll running in injected script:
554555
// - streams logs into progress;
555556
// - cancels the poll when progress cancels.
556-
export class InjectedScriptPollHandler {
557+
export class InjectedScriptPollHandler<T> {
557558
private _progress: Progress;
558-
private _poll: js.JSHandle<types.InjectedScriptPoll<any>> | null;
559+
private _poll: js.JSHandle<types.InjectedScriptPoll<T>> | null;
559560

560-
constructor(progress: Progress, poll: js.JSHandle<types.InjectedScriptPoll<any>>) {
561+
constructor(progress: Progress, poll: js.JSHandle<types.InjectedScriptPoll<T>>) {
561562
this._progress = progress;
562563
this._poll = poll;
563564
this._progress.cleanupWhenAborted(() => this.cancel());
@@ -577,6 +578,35 @@ export class InjectedScriptPollHandler {
577578
});
578579
}
579580

581+
async finishHandle(): Promise<types.SmartHandle<T>> {
582+
try {
583+
const result = await this._poll!.evaluateHandle(poll => poll.result);
584+
await this._finishInternal();
585+
return result;
586+
} finally {
587+
this.cancel();
588+
}
589+
}
590+
591+
async finish(): Promise<T> {
592+
try {
593+
const result = await this._poll!.evaluate(poll => poll.result);
594+
await this._finishInternal();
595+
return result;
596+
} finally {
597+
this.cancel();
598+
}
599+
}
600+
601+
private async _finishInternal() {
602+
if (!this._poll)
603+
return;
604+
// Retrieve all the logs before continuing.
605+
const messages = await this._poll.evaluate(poll => poll.takeLastLogs()).catch(e => [] as string[]);
606+
for (const message of messages)
607+
this._progress.log(apiLog, message);
608+
}
609+
580610
cancel() {
581611
if (!this._poll)
582612
return;

‎src/frames.ts

Lines changed: 6 additions & 14 deletions
Original file line numberDiff line numberDiff line change
@@ -345,7 +345,7 @@ export class Frame {
345345
const progressController = new ProgressController(this._page, this._page._timeoutSettings.navigationTimeout(options));
346346
abortProgressOnFrameDetach(progressController, this);
347347
return progressController.run(async progress => {
348-
progress.log(apiLog, `${progress.apiName}("${url}"), waiting until "${options.waitUntil || 'load'}"`);
348+
progress.log(apiLog, `navigating to "${url}", waiting until "${options.waitUntil || 'load'}"`);
349349
const headers = (this._page._state.extraHTTPHeaders || {});
350350
let referer = headers['referer'] || headers['Referer'];
351351
if (options.referer !== undefined) {
@@ -455,7 +455,7 @@ export class Frame {
455455
throw new Error(`Unsupported waitFor option "${state}"`);
456456
const { world, task } = selectors._waitForSelectorTask(selector, state);
457457
return runAbortableTask(async progress => {
458-
progress.log(apiLog, `Waiting for selector "${selector}"${state === 'attached' ? '' : ' to be ' + state}...`);
458+
progress.log(apiLog, `waiting for selector "${selector}"${state === 'attached' ? '' : ' to be ' + state}`);
459459
const result = await this._scheduleRerunnableTask(progress, world, task);
460460
if (!result.asElement()) {
461461
result.dispose();
@@ -524,12 +524,11 @@ export class Frame {
524524
abortProgressOnFrameDetach(progressController, this);
525525
return progressController.run(async progress => {
526526
const waitUntil = options.waitUntil === undefined ? 'load' : options.waitUntil;
527-
progress.log(apiLog, `${progress.apiName}(), waiting until "${waitUntil}"`);
527+
progress.log(apiLog, `setting frame content, waiting until "${waitUntil}"`);
528528
const tag = `--playwright--set--content--${this._id}--${++this._setContentCounter}--`;
529529
const context = await this._utilityContext();
530530
const lifecyclePromise = new Promise((resolve, reject) => {
531531
this._page._frameManager._consoleMessageTags.set(tag, () => {
532-
progress.log(apiLog, 'content written');
533532
// Clear lifecycle right after document.open() - see 'tag' below.
534533
this._page._frameManager.clearFrameLifecycle(this);
535534
this._waitForLoadState(progress, waitUntil).then(resolve).catch(reject);
@@ -710,13 +709,11 @@ export class Frame {
710709
selector: string, options: types.TimeoutOptions,
711710
action: (progress: Progress, handle: dom.ElementHandle<Element>) => Promise<R>): Promise<R> {
712711
return runAbortableTask(async progress => {
713-
progress.log(apiLog, `${progress.apiName}("${selector}")`);
714712
while (progress.isRunning()) {
715713
try {
714+
progress.log(apiLog, `waiting for selector "${selector}"`);
716715
const { world, task } = selectors._waitForSelectorTask(selector, 'attached');
717-
progress.log(apiLog, `waiting for the selector "${selector}"`);
718716
const handle = await this._scheduleRerunnableTask(progress, world, task);
719-
progress.log(apiLog, `...got element for the selector`);
720717
const element = handle.asElement() as dom.ElementHandle<Element>;
721718
progress.cleanupWhenAborted(() => element.dispose());
722719
const result = await action(progress, element);
@@ -915,16 +912,11 @@ class RerunnableTask<T> {
915912
}
916913

917914
async rerun(context: dom.FrameExecutionContext) {
918-
let pollHandler: dom.InjectedScriptPollHandler | null = null;
919915
try {
920-
const poll = await this._task(context);
921-
pollHandler = new dom.InjectedScriptPollHandler(this._progress, poll);
922-
const result = await poll.evaluateHandle(poll => poll.result);
916+
const pollHandler = new dom.InjectedScriptPollHandler(this._progress, await this._task(context));
917+
const result = await pollHandler.finishHandle();
923918
this._resolve(result);
924919
} catch (e) {
925-
if (pollHandler)
926-
pollHandler.cancel();
927-
928920
// When the page is navigated, the promise is rejected.
929921
// We will try again in the new execution context.
930922
if (e.message.includes('Execution context was destroyed'))

‎src/injected/injectedScript.ts

Lines changed: 26 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -165,6 +165,7 @@ export default class InjectedScript {
165165
logs,
166166
result: poll(progress),
167167
cancel: () => { progress.canceled = true; },
168+
takeLastLogs: () => currentLogs,
168169
};
169170
}
170171

@@ -448,12 +449,34 @@ export default class InjectedScript {
448449
}
449450

450451
previewElement(element: Element): string {
451-
const id = element.id ? '#' + element.id : '';
452-
const classes = Array.from(element.classList).map(c => '.' + c).join('');
453-
return `${element.nodeName.toLowerCase()}${id}${classes}`;
452+
const attrs = [];
453+
for (let i = 0; i < element.attributes.length; i++) {
454+
if (element.attributes[i].name !== 'style')
455+
attrs.push(` ${element.attributes[i].name}="${element.attributes[i].value}"`);
456+
}
457+
attrs.sort((a, b) => a.length - b.length);
458+
let attrText = attrs.join('');
459+
if (attrText.length > 50)
460+
attrText = attrText.substring(0, 49) + '\u2026';
461+
if (autoClosingTags.has(element.nodeName))
462+
return `<${element.nodeName.toLowerCase()}${attrText}/>`;
463+
464+
const children = element.childNodes;
465+
let onlyText = false;
466+
if (children.length <= 5) {
467+
onlyText = true;
468+
for (let i = 0; i < children.length; i++)
469+
onlyText = onlyText && children[i].nodeType === Node.TEXT_NODE;
470+
}
471+
let text = onlyText ? (element.textContent || '') : '';
472+
if (text.length > 50)
473+
text = text.substring(0, 49) + '\u2026';
474+
return `<${element.nodeName.toLowerCase()}${attrText}>${text}</${element.nodeName.toLowerCase()}>`;
454475
}
455476
}
456477

478+
const autoClosingTags = new Set(['AREA', 'BASE', 'BR', 'COL', 'COMMAND', 'EMBED', 'HR', 'IMG', 'INPUT', 'KEYGEN', 'LINK', 'MENUITEM', 'META', 'PARAM', 'SOURCE', 'TRACK', 'WBR']);
479+
457480
const eventType = new Map<string, 'mouse'|'keyboard'|'touch'|'pointer'|'focus'|'drag'>([
458481
['auxclick', 'mouse'],
459482
['click', 'mouse'],

‎src/progress.ts

Lines changed: 9 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -14,7 +14,7 @@
1414
* limitations under the License.
1515
*/
1616

17-
import { InnerLogger, Log } from './logger';
17+
import { InnerLogger, Log, apiLog } from './logger';
1818
import { TimeoutError } from './errors';
1919
import { assert } from './helper';
2020
import { getCurrentApiCall, rewriteErrorMessage } from './debug/stackTrace';
@@ -82,11 +82,15 @@ export class ProgressController {
8282
runCleanup(cleanup);
8383
},
8484
log: (log: Log, message: string | Error) => {
85-
if (this._state === 'running')
85+
if (this._state === 'running') {
8686
this._logRecording.push(message.toString());
87-
this._logger._log(log, message);
87+
this._logger._log(log, ' ' + message);
88+
} else {
89+
this._logger._log(log, message);
90+
}
8891
},
8992
};
93+
this._logger._log(apiLog, `=> ${this._apiName} started`);
9094

9195
const timeoutError = new TimeoutError(`Timeout ${this._timeout}ms exceeded during ${this._apiName}.`);
9296
const timer = setTimeout(() => this._forceAbort(timeoutError), progress.timeUntilDeadline());
@@ -96,13 +100,15 @@ export class ProgressController {
96100
clearTimeout(timer);
97101
this._state = 'finished';
98102
this._logRecording = [];
103+
this._logger._log(apiLog, `<= ${this._apiName} succeeded`);
99104
return result;
100105
} catch (e) {
101106
this._aborted();
102107
rewriteErrorMessage(e, e.message + formatLogRecording(this._logRecording, this._apiName));
103108
clearTimeout(timer);
104109
this._state = 'aborted';
105110
this._logRecording = [];
111+
this._logger._log(apiLog, `<= ${this._apiName} failed`);
106112
await Promise.all(this._cleanups.splice(0).map(cleanup => runCleanup(cleanup)));
107113
throw e;
108114
}

‎src/selectors.ts

Lines changed: 11 additions & 24 deletions
Original file line numberDiff line numberDiff line change
@@ -120,38 +120,25 @@ export class Selectors {
120120

121121
return injected.poll('raf', (progress: types.InjectedScriptProgress) => {
122122
const element = injected.querySelector(parsed, document);
123+
const visible = element ? injected.isVisible(element) : false;
123124

124-
const log = (suffix: string) => {
125-
if (lastElement === element)
126-
return;
125+
if (lastElement !== element) {
127126
lastElement = element;
128127
if (!element)
129-
progress.log(`selector did not resolve to any element`);
128+
progress.log(` selector did not resolve to any element`);
130129
else
131-
progress.log(`selector resolved to "${injected.previewElement(element)}"${suffix ? ' ' + suffix : ''}`);
132-
};
130+
progress.log(` selector resolved to ${visible ? 'visible' : 'hidden'} ${injected.previewElement(element)}`);
131+
}
133132

134133
switch (state) {
135-
case 'attached': {
134+
case 'attached':
136135
return element || false;
137-
}
138-
case 'detached': {
139-
if (element)
140-
log('');
136+
case 'detached':
141137
return !element;
142-
}
143-
case 'visible': {
144-
const result = element && injected.isVisible(element) ? element : false;
145-
if (!result)
146-
log('that is not visible');
147-
return result;
148-
}
149-
case 'hidden': {
150-
const result = !element || !injected.isVisible(element);
151-
if (!result)
152-
log('that is still visible');
153-
return result;
154-
}
138+
case 'visible':
139+
return visible ? element : false;
140+
case 'hidden':
141+
return !visible;
155142
}
156143
});
157144
}, { parsed, state });

‎src/types.ts

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -176,6 +176,7 @@ export type InjectedScriptLogs = { current: string[], next: Promise<InjectedScri
176176
export type InjectedScriptPoll<T> = {
177177
result: Promise<T>,
178178
logs: Promise<InjectedScriptLogs>,
179+
takeLastLogs: () => string[],
179180
cancel: () => void,
180181
};
181182

0 commit comments

Comments
 (0)