Closed Bug 1608931 Opened 6 years ago Closed 6 years ago

A huge amount of Puppeteer unit tests hang in `Runtime.callFunctionOn` when using IntersectionObserver

Categories

(Core :: Layout, defect, P1)

Product:
Core
Component:
Layout
Type:
defect

Tracking

()

Status:
RESOLVED FIXED
Milestone:
mozilla74
Tracking Flags:
Tracking Status
firefox74 --- fixed

People

(Reporter: whimboo, Assigned: emilio)

References

Details

(Keywords: hang)

Attachments

(3 files)

Bug 1608931 - Ensure we tick the refresh driver at least once after calling IntersectionObserver.observe. r=mstange
47 bytes, text/x-phabricator-request
Details | Review
Selection Test.html
946 bytes, text/html
Details
Bug 1608931 - followup: fix subtle unintended behavior change.
47 bytes, text/x-phabricator-request
Details | Review

Basically nearly all the tests in click.spec.js hang in the Runtime.callFunctionOn method, and as such the tests time out like:

1) Firefox Browser Page Page.click should click on checkbox label and toggle (click.spec.js:156:5)
  Message:
    Timeout Exceeded 10000ms

Here the call which causes our end-point to hang:

  puppeteer:protocol SEND ► {"sessionId":1,"method":"Runtime.callFunctionOn","params":{"functionDeclaration":"async(element, pageJavascriptEnabled) => {\n      if (!element.isConnected)\n        return 'Node is detached from document';\n      if (element.nodeType !== Node.ELEMENT_NODE)\n        return 'Node is not of type HTMLElement';\n      // force-scroll if page's javascript is disabled.\n      if (!pageJavascriptEnabled) {\n        element.scrollIntoView({block: 'center', inline: 'center', behavior: 'instant'});\n        return false;\n      }\n      const visibleRatio = await new Promise(resolve => {\n        const observer = new IntersectionObserver(entries => {\n          resolve(entries[0].intersectionRatio);\n          observer.disconnect();\n        });\n        observer.observe(element);\n      });\n      if (visibleRatio !== 1.0)\n        element.scrollIntoView({block: 'center', inline: 'center', behavior: 'instant'});\n      return false;\n    }\n//# sourceURL=__puppeteer_evaluation_script__\n","executionContextId":4,"arguments":[{"objectId":"975f0fe5-ec3a-c141-9816-de0521eb5119"},{"value":true}],"returnByValue":true,"awaitPromise":true,"userGesture":true},"id":22} +0ms

I will put this into the reserve for now given that seems to be important. Maybe we just miss to wait correctly for a Promise to be resolved? The function the above code comes from is _scrollIntoViewIfNeeded from JSHandle.js.

The problem is that the IntersectionObserver never fires it's callback:
https://searchfox.org/mozilla-central/rev/9e45d74b956be046e5021a746b0c8912f1c27318/remote/test/puppeteer/lib/JSHandle.js#191-197

I seem to fail to parse this method. Where is actually an activity triggered which changes the intersection of the element? We seem to wait forever for that. Maybe Chrome has a different implementation? Andreas or Maja, do you both know more about this class? If not we might want to reach out to someone from the DOM team.

Interesting is that when I run such a test in non-headless mode I only have to move the mouse a bit anywhere in the content area to make this test passing.

And running with Chrome I get the following 3 life cycle events logged before the Promise gets resolved:

  puppeteer:protocol ◀ RECV {"method":"Page.lifecycleEvent","params":{"frameId":"5F87880D2B7B4033CD6C1A16923CBE56","loaderId":"0F4D7D1F0254AF6217814F660B59FF45","name":"firstPaint","timestamp":43242.4669},"sessionId":"26D5DB4CD4AEE5CC277EBAAB8E74ECD4"} +8ms
  puppeteer:protocol ◀ RECV {"method":"Page.lifecycleEvent","params":{"frameId":"5F87880D2B7B4033CD6C1A16923CBE56","loaderId":"0F4D7D1F0254AF6217814F660B59FF45","name":"firstContentfulPaint","timestamp":43242.4669},"sessionId":"26D5DB4CD4AEE5CC277EBAAB8E74ECD4"} +0ms
  puppeteer:protocol ◀ RECV {"method":"Page.lifecycleEvent","params":{"frameId":"5F87880D2B7B4033CD6C1A16923CBE56","loaderId":"0F4D7D1F0254AF6217814F660B59FF45","name":"firstMeaningfulPaintCandidate","timestamp":43242.4669},"sessionId":"26D5DB4CD4AEE5CC277EBAAB8E74ECD4"} +0ms

Concerns about callFunctionOn have come up before. In each case so far, we've found that it was actually some other underlying issue, e.g. the command times out waiting for a function that is checking that the viewport is resized. I think it makes more sense to re-purpose this bug for a specific reason for timeout, like my example.

Sure, we can make this bug specific to the IntersectionObserver usage.

So read a bit about this kind of observer, and as used in Puppeteer (link see comment 1) no options are specified. That means that every property in options will receive the defaults. threshold will be 0, which means that at the moment when the element is fully visible in the viewport the callback has to be executed. But that is not happening.

Here an simplified HTML document: https://output.jsbin.com/qazaninala

Open Firefox's devtools and run the following code in the console:

var element = document.getElementById("agree");
new Promise(resolve => {
  const observer = new IntersectionObserver(entries => {
    resolve(entries[0].intersectionRatio);
    observer.disconnect();
  });
  observer.observe(element);
}).then(visibleRatio => {
  alert(visibleRatio);
});

The promise doesn't resolve while the mouse doesn't hover over the visible viewport. In Chrome it resolves immediately.

Olli, could this be a bug with IntersectionObserver?

Flags: needinfo?(bugs)
Summary: A huge amount of Puppeteer unit tests hang in `Runtime.callFunctionOn` → A huge amount of Puppeteer unit tests hang in `Runtime.callFunctionOn` when using IntersectionObserver

IntersectionObserver is more a layout thingie. Perhaps emilio knows about it, or knows who knows.

Flags: needinfo?(bugs) → needinfo?(emilio)

Which OS was comment 5 on? I get the promise resolved just fine on Linux.

Intersection observer notifications happen at each refresh driver tick... Does the promise resolve if you force the refresh driver to run by doing something like requestAnimationFrame(() => {}) or such?

It may be that IntersectionObserver doesn't schedule the refresh driver to run itself, and / or that we throttle it somehow.

Not sure if creating an intersection observer should force the refresh driver to tick...

Flags: needinfo?(emilio)

This was tested with Mozilla/5.0 (Macintosh; Intel Mac OS X 10.14; rv:74.0) Gecko/20100101 Firefox/74.0 ID:20200112214546.

Forcing the refresh driver to run makes it indeed work for me, and the callback is fired immediately. So there might be a OS specific code path which we don't hit on MacOS? Note that I haven't tested on Windows yet.

Flags: needinfo?(emilio)

Please note that I also tried it with Linux Mint inside of VirtualBox, and it is also not working for me with that OS. Maybe you had your mouse inside the viewport when checking my steps?

I'm using Wayland, that's probably why. Pretty sure I didn't have a mouse in the viewport.

Anyhow... So in Gecko it seems to me there's no guarantee for the refresh driver to fire as a result of an intersection observation being created.

I guess this piece of the spec, in particular step 5 is what is supposed to do this:

  1. Schedule an iteration of the event loop in the root's browsing context.

Though I don't think that sentence is particularly well defined.

Flags: needinfo?(emilio)

Could you give the patch a try and ensure that it fixes your issue? I'm running it through try atm (if it's green I'll send it for review I suppose).

Flags: needinfo?(hskupin)
Assignee: nobody → emilio
Status: NEW → ASSIGNED
Priority: P3 → P1

I will have a look when the build is ready.

Component: Agent → Layout
Product: Remote Protocol → Core

The try build is here:
https://treeherder.mozilla.org/#/jobs?repo=try&tier=1%2C2%2C3&revision=45206046b01dc195f432e3d5cbd44049bd087ca3

I also submitted a puppeteer job to see if we are doing already better with just this patch.

Emilio, I tested your build now and it is still not working with the Puppeteer test, but I can see a bit of changed behavior in Firefox when running my testcase manually. I don't need the mouse in the visible viewport anymore.

Maybe you should really try to run the test yourself. Here the steps:

  1. Goto /remote/test/puppeteer/test/click.spec.js and change line 156 from it( to fit(.
  2. Run DEBUG="puppeteer:*" mach puppeteer-test

By using fit you will instruct the test harness to only run this single test. And that is the one which is failing for me still. Only when moving the mouse the checkbox is getting checked. So maybe there is really another part left to do.

Flags: needinfo?(hskupin) → needinfo?(emilio)

Also the try job for Puppeteer is still failing with:

[task 2020-01-15T17:42:20.472Z] 25) Firefox Browser Page Page.click should click on checkbox label and toggle (click.spec.js:156:5)
[task 2020-01-15T17:42:20.472Z]   Message:
[task 2020-01-15T17:42:20.472Z]     Timeout Exceeded 10000ms

Emilio, please let me know if there is anything else I can help with.

So I can repro the failure, and I'll take a look, but fwiw... There's no easy way to launch firefox under a debugger for that test suite, looks like. I tried the obvious --debugger=rr and such. In the end I hacked it up like this:

diff --git a/remote/test/puppeteer/lib/Launcher.js b/remote/test/puppeteer/lib/Launcher.js
index ceb57463db4f..2b5d662d51fb 100644
--- a/remote/test/puppeteer/lib/Launcher.js
+++ b/remote/test/puppeteer/lib/Launcher.js
@@ -390,7 +390,16 @@ class FirefoxLauncher {
       extraPrefsFirefox = {}
     } = options;
 
-    const firefoxArguments = [];
+    let executable = executablePath;
+    if (!executablePath) {
+      const {missingText, executablePath} = resolveExecutablePath(this);
+      if (missingText)
+        throw new Error(missingText);
+      executable = executablePath;
+    }
+
+    const firefoxArguments = [executable];
+    executable = '/usr/local/bin/rr';
     if (!ignoreDefaultArgs)
       firefoxArguments.push(...this.defaultArgs(options));
     else if (Array.isArray(ignoreDefaultArgs))
@@ -406,13 +415,6 @@ class FirefoxLauncher {
       firefoxArguments.push(temporaryUserDataDir);
     }
 
-    let executable = executablePath;
-    if (!executablePath) {
-      const {missingText, executablePath} = resolveExecutablePath(this);
-      if (missingText)
-        throw new Error(missingText);
-      executable = executablePath;
-    }
 
     const runner = new BrowserRunner(executable, firefoxArguments, temporaryUserDataDir);
     runner.start({handleSIGHUP, handleSIGTERM, handleSIGINT, dumpio, env, pipe});

But a debug build running under rr is slower so I always hit:

puppeteer.spec.js:90:5 - Timeout Exceeded 10000ms while running "beforeAll" in suite "Firefox Browser"

I eventually figured where the 10 seconds came from and that I could override it using the TIMEOUT variable but it took a bit... Exposing this stuff from ./mach puppeteer-test --help or such would've been great.

Flags: needinfo?(emilio)

Well, and the hack above didn't work because it kills the rr process abnormally and thus the trace doesn't finish.

Attachment #9121051 - Attachment description: Bug 1608931 - Ensure we tick the refresh driver at least once after calling IntersectionObserver.observe. → Bug 1608931 - Ensure we tick the refresh driver at least once after calling IntersectionObserver.observe. r=mstange

Tweaked the patch a bit, mind giving it a shot and confirming it fixes the issue for you too?

Flags: needinfo?(hskupin)

I tried to write a WPT test for this but I couldn't get it to fail without my patch... :/

FWIW, the way I was trying is:

<!doctype html>
<meta name="viewport" content="width=device-width,initial-scale=1">
<script src="/resources/testharness.js"></script>
<script src="/resources/testharnessreport.js"></script>
<link rel="author" href="mailto:emilio@crisal.io" title="Emilio Cobos Álvarez">
<link rel="author" href="https://mozilla.org" title="Mozilla">
<link rel="help" href="https://bugzilla.mozilla.org/show_bug.cgi?id=1608931">
<link rel="help" href="https://w3c.github.io/IntersectionObserver/#dom-intersectionobserver-observe">
<div id="observe">Observe me</div>
<script>
const t = async_test("IntersectionObserver.observe schedules a rendering update to call the callback as needed if intersecting");

onload = t.step_func(function() {
  requestIdleCallback(t.step_func(function() {
    const element = document.getElementById("observe");
    const observer = new IntersectionObserver(t.step_func_done(function(entries) {
      assert_true(entries[0].intersectionRatio > 0, "Element is intersecting");
    }));
    observer.observe(element);
  }));
});
</script>

(In reply to Emilio Cobos Álvarez (:emilio) from comment #20)

Tweaked the patch a bit, mind giving it a shot and confirming it fixes the issue for you too?

Can you please point me to a try build? If you can trigger a MacOS opt/debug build that would be great. I will be back later today and would be able to use those builds for testing.

Flags: needinfo?(hskupin) → needinfo?(emilio)

Oh, I think it's:
https://treeherder.mozilla.org/#/jobs?repo=try&tier=1%2C2%2C3&revision=97e61a91623691c316c303826a45500aec2e64a0

I will trigger the Mac builds quickly before heading out.

Flags: needinfo?(emilio) → needinfo?(hskupin)

Emilio, this works great! I just run the tests locally (also by enabling more in that file via fdescribe) and even alone in this file we pass 8 more tests now! I've also triggered puppeteer tests for that try build:

https://treeherder.mozilla.org/#/jobs?repo=try&tier=1%2C2%2C3&revision=40eb17959a28f7ec6509b34c4a20b42b59633f8d&selectedJob=285673589

These aren't done yet, and I will report back once they are. Let me see if I can somewhat modify your wpt test to actually make it failing locally. Maybe there is something specific the Puppeteer test is doing.

Flags: needinfo?(hskupin)

Puppeteer tests finished and it remains with 8 more passing tests:
https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=285673589&repo=try&lineNumber=46196

Emilio, mind updating the bugs summary?

Attached file Selection Test.html —

Emilio, this is the testcase as used by Puppeteer. Maybe it is related to the additional event handling? Use my code from comment 5 from inside the devtool's console, and you can see that the Promise is never resolved. For me that reproduces each and every time. With your build it is fixed.

Hm, could it be that this only happens when the IntersectionObserver code is run inside a framescript or JSWindowActorClient but not in the web page itself? Even if I strip down the above HTML testcase to only some lines it is still reproducible for me via the devtools console. But once that code is part of the web page, it just works.

Yeah, that sounds likely...

Pushed by ealvarez@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/9886115cd686 Ensure we tick the refresh driver at least once after calling IntersectionObserver.observe. r=mstange

This can fire in some tests that take over the refresh driver via script.

Pushed by ealvarez@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/842e205217bf followup: fix subtle unintended behavior change.

Great work! With the patch landed on autoland I can see 11 more tests passing from the Puppeteer unit test suite. Thanks a lot Emilio!

https://hg.mozilla.org/mozilla-central/rev/9886115cd686
https://hg.mozilla.org/mozilla-central/rev/842e205217bf

Status: ASSIGNED → RESOLVED
Closed: 6 years ago
status-firefox74: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla74
Whiteboard: [puppeteer-beta-reserve]
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: