1832778 - `script.callFunction` on MacOS errors with: "AbortError: Actor 'MessageHandlerFrame' destroyed before query 'MessageHandlerFrameParent:sendCommand' was resolved"

Status: RESOLVED FIXED

(Remote Protocol :: WebDriver BiDi, defect, P3)

Description

[Nik]

Steps to reproduce:

Using the latest Nightly. Using webDriverBiDi. I run CI for Puppeteer.
We update our code to clean the pages it creates https://github.com/puppeteer/puppeteer/blob/main/packages/puppeteer-core/src/common/bidi/Page.ts#L136
Previously we closed the browser.
Tests started failing only for MacOS. Ubuntu tests pass.
The 'remote.log.level': 'Trace' was set, but no traces were reported
A test that fails which to search the logs is should modify global environment

Actual results:

Test A:

1. Creates a page - browsingContext.create with {type: 'tab'}
   1.1) Note: We are calling a command that does not exits cdp.getSession , that
   returns an error as expected.
2. Test run - script.callFunction with {"id":90,"method":"script.callFunction","params":{"functionDeclaration":"() => {\\n return (globalThis.globalVar = 123);\\n }\\n//# sourceURL=pptr:evaluate;Q29udGV4dC48YW5vbnltb3VzPiAoL1VzZXJzL3J1bm5lci93b3JrL3B1cHBldGVlci9wdXBwZXRlZXIvdGVzdC9idWlsZC9ldmFsdWF0aW9uLnNwZWMuanM6ODY6MjQp\\n","arguments":[],"target":{"context":"<id>"},"resultOwnership":"none","awaitPromise":true}}
3. Correct result is return
4. browsingContext.close
5. Rerun the test from 1)
6. Eventually the return for id=90 will return
   {"id":90,"error":"unknown error","message":"AbortError: Actor 'MessageHandlerFrame' destroyed before query 'MessageHandlerFrameParent:sendCommand' was resolved","stacktrace":""}

Expected results:

Calling BrowsingContext.close with Id=X should not affect commands commands send to context = Y.

Comment 1

[Nik]

Attachment: firefox-bidi-macOS.txt

Comment 2

[Henrik Skupin [:whimboo][⌚️UTC+2] (away 07/21 - 08/08)]

Nik, do you have a Puppeteer script that we could run to reproduce this issue? That would be pretty helpful.

Also the trace logs might give an indication what's wrong here. I assume that the tab gets closed or unloaded - maybe due to a content crash. But without the trace log it's just a guess.

Comment 3

[Julian Descottes [:jdescottes]]

Could you also try to add a small delay before the script.callFunction which fails? I am suspecting that browsingContext.create resolves too early and that the tab is still on a temporary about:blank document when you send that callFunction command

Comment 4

[Nik]

I will provide traces, a variable was not set on our end to pipe the Firefox output to console.
For the Puppeteer Script a lot of them fail all revolve around the script.callFunction and different test fail each run, so far only this command has shown this issue. You can run the evaluation.spec.ts as it has the most calls to this command.
Note: It's only happening on this branch bidi-frames https://github.com/puppeteer/puppeteer/pull/10121 . Previously we did not handle correctly the closing of pages and relayed on the browser closing after each test file.

import puppeteer from "puppeteer";
async function main() {
  const browser = await puppeteer.launch({
    product: "firefox",
    protocol: "webDriverBiDi",
  });
  async function evaluate() {
    const context = await browser.createIncognitoBrowserContext();
    const page = await context.newPage();
    await page.evaluate(() => {
      return (globalThis.globalVar = 123);
    });
    const value = await page.evaluate("globalVar");
    console.log(value);
    await context.close();
  }
  for (const _ of Array(10)) {
    await evaluate();
  }
  await browser.close();
}
main();

As for the small delay we send a command with the newly created context (session.subscribe and cdp.getSession [which we expect to fail for Firefox]) and wait for them to arrive so there should be some time after the creation and the evaluation.

Comment 5

[Nik]

Attachment: firefox-bidi-macOS.txt

Log now includes Traces

Comment 6

[Julian Descottes [:jdescottes]]

So I can see that in the failing cases, the initial navigation fails to be detected:

2023-05-12T13:26:12.4670510Z 1683897972428	RemoteAgent	TRACE	[31] ProgressListener Setting unload timer (200ms)
2023-05-12T13:26:12.8071420Z 2023-05-12T13:26:12.800Z puppeteer:webDriverBiDi:RECV â—€ [
2023-05-12T13:26:12.8072030Z 1683897972799	RemoteAgent	TRACE	[31] ProgressListener No navigation detected: about:blank
2023-05-12T13:26:12.8117520Z   '{"id":117,"result":{"context":"25e5f76a-b956-4e70-8cfb-d3d84eb84d07"}}'
2023-05-12T13:26:12.8118140Z 1683897972799	RemoteAgent	TRACE	[31] ProgressListener Stop: has error=false

As for the small delay we send a command with the newly created context (session.subscribe and cdp.getSession [which we expect to fail for Firefox]) and wait for them to arrive so there should be some time after the creation and the evaluation

That seems to take only a few hundred ms. I don't know the performance of the machines you have in CI, but it might not be enough. Again I think it would be interesting for the investigation to have a decent delay after using browsingContext.create. On our CI, for slow platforms we multiply the initial 200ms timeout by either 8 or 16. So that's much bigger than the delay caused by subscribe+cdp.getSession.

We should really make that timeout configurable with a pref so that you could set custom values for your CI as well.

Could you try to add a delay and see if that helps on your CI?

FWIW, I pulled the branch locally and couldn't reproduce the issue on macos.

Comment 7

[Julian Descottes [:jdescottes]]

Any update here? Are you still blocked on this or did you manage to get the tests to pass?

Comment 8

[Julian Descottes [:jdescottes]]

We have been trying a fix for the issue about missed navigation which I mentioned earlier in this thread.
If you are still consistently reproducing the issue, would it be possible for you to test with build from https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/dci8elH5TZChCEtUX5G_Pg/runs/0/artifacts/public/build/target.dmg . For context, this is the DMG which was built for the following CI job: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/dci8elH5TZChCEtUX5G_Pg/runs/0/artifacts/public/build/target.dmg

It would be super helpful for us to know if this fixes the issue on your side.

Comment 9

[Julian Descottes [:jdescottes]]

According to CI runs on https://github.com/puppeteer/puppeteer/pull/10333 it looks like the fix from Bug 1832891 addresses the issue, so my earlier suggestion was most likely correct but no need to keep the needinfos.

This is tracked upstream at https://github.com/puppeteer/puppeteer/pull/10333, so let's close this when the PR gets merged.