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

@@ -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<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 {
+  private _progress: Progress;
+  private _poll: js.JSHandle<types.InjectedScriptPoll<any>> | null;
+
+  constructor(progress: Progress, poll: js.JSHandle<types.InjectedScriptPoll<any>>) {
+    this._progress = progress;
+    this._poll = poll;
+    this._progress.cleanupWhenCanceled(() => this.cancel());
+    this._streamLogs(poll.evaluateHandle(poll => poll.logs));
+  }
+
+  private _streamLogs(logsPromise: Promise<js.JSHandle<types.InjectedScriptLogs>>) {
+    // 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,

src/frames.ts

@@ -898,7 +898,7 @@ export class Frame {
   }
 }
 
-export type SchedulableTask<T> = (context: dom.FrameExecutionContext) => Promise<js.JSHandle<types.CancelablePoll<T>>>;
+export type SchedulableTask<T> = (context: dom.FrameExecutionContext) => Promise<js.JSHandle<types.InjectedScriptPoll<T>>>;
 
 class RerunnableTask<T> {
   readonly promise: Promise<types.SmartHandle<T>>;
@@ -919,29 +919,19 @@ class RerunnableTask<T> {
   }
 
   terminate(error: Error) {
-    this._progress.cancel(error);
+    this._reject(error);
   }
 
   async rerun(context: dom.FrameExecutionContext) {
-    let poll: js.JSHandle<types.CancelablePoll<T>> | 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.

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> = () => T | Falsy;
-type InjectedScriptProgress = {
-  canceled: boolean;
-};
-
-function asCancelablePoll<T>(result: T): types.CancelablePoll<T> {
-  return { result: Promise.resolve(result), cancel: () => {} };
-}
+type Predicate<T> = (progress: types.InjectedScriptProgress) => T | Falsy;
 
 export default class InjectedScript {
   readonly engines: Map<string, SelectorEngine>;
@@ -111,14 +104,14 @@ export default class InjectedScript {
     return rect.width > 0 && rect.height > 0;
   }
 
-  private _pollRaf<T>(progress: InjectedScriptProgress, predicate: Predicate<T>): Promise<T> {
+  private _pollRaf<T>(progress: types.InjectedScriptProgress, predicate: Predicate<T>): Promise<T> {
     let fulfill: (result: T) => void;
     const result = new Promise<T>(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<T>(progress: InjectedScriptProgress, pollInterval: number, predicate: Predicate<T>): Promise<T> {
+  private _pollInterval<T>(progress: types.InjectedScriptProgress, pollInterval: number, predicate: Predicate<T>): Promise<T> {
     let fulfill: (result: T) => void;
     const result = new Promise<T>(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<T>(polling: 'raf' | number, predicate: Predicate<T>): types.CancelablePoll<T> {
-    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<T>(poll: (progess: types.InjectedScriptProgress) => Promise<T>): types.InjectedScriptPoll<T> {
+    let currentLogs: string[] = [];
+    let logReady = () => {};
+    const createLogsPromise = () => new Promise<types.InjectedScriptLogs>(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<T>(polling: 'raf' | number, predicate: Predicate<T>): types.InjectedScriptPoll<T> {
+    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<types.InjectedScriptResult> {
-    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<types.InjectedScriptResult> {
+    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<string, 'mouse'|'keyboard'|'touch'|'pointer'|'focus'|'drag'>([

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

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

src/types.ts

@@ -169,7 +169,14 @@ export type InjectedScriptResult<T = undefined> =
   { status: 'notconnected' } |
   { status: 'error', error: string };
 
-export type CancelablePoll<T> = {
+export type InjectedScriptProgress = {
+  canceled: boolean,
+  log: (message: string) => void,
+};
+
+export type InjectedScriptLogs = { current: string[], next: Promise<InjectedScriptLogs> };
+export type InjectedScriptPoll<T> = {
   result: Promise<T>,
+  logs: Promise<InjectedScriptLogs>,
   cancel: () => void,
 };

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');