1853988 - InvalidStateError: JSWindowActorChild.sendAsyncMessage: JSWindowActorChild cannot send at the moment: _onRegistryEvent@chrome://remote/content/shared/messagehandler/transports/js-window-actors/MessageHandlerFrameChild.sys.mjs:101:10

Status: NEW

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

Description

[Henrik Skupin [:whimboo][⌚️UTC+2]]

The Puppeteer test [navigation.spec] navigation Page.goto should return last response in redirect chain fails because redirects cause both the browsingContext.domContentLoaded and browsingContext.load events to fail:

 0:04.74 pid:2589   InvalidStateError: JSWindowActorChild.sendAsyncMessage: JSWindowActorChild cannot send at the moment: _onRegistryEvent@chrome://remote/content/shared/messagehandler/transports/js-window-actors/MessageHandlerFrameChild.sys.mjs:101:10
 0:04.74 pid:2589 emit@resource://gre/modules/EventEmitter.sys.mjs:154:20
 0:04.74 pid:2589 _onMessageHandlerEvent@chrome://remote/content/shared/messagehandler/MessageHandlerRegistry.sys.mjs:234:10
 0:04.74 pid:2589 emit@resource://gre/modules/EventEmitter.sys.mjs:154:20
 0:04.74 pid:2589 emitEvent@chrome://remote/content/shared/messagehandler/MessageHandler.sys.mjs:178:10
 0:04.74 pid:2589 emitEvent@chrome://remote/content/shared/messagehandler/Module.sys.mjs:54:25
 0:04.74 pid:2589 #onDOMContentLoaded@chrome://remote/content/webdriver-bidi/modules/windowglobal/browsingContext.sys.mjs:105:12
 0:04.74 pid:2589 emit@resource://gre/modules/EventEmitter.sys.mjs:154:20
 0:04.74 pid:2589 #onDOMContentLoaded@chrome://remote/content/shared/listeners/LoadListener.sys.mjs:92:12
 0:04.74 pid:2589

This can be reproduced pretty easily by changing the test to:

    it.only('should return last response in redirect chain', async () => {
      const {page, server} = await getTestState();

      server.setRedirect('/redirect/1.html', server.EMPTY_PAGE);
      // server.setRedirect('/redirect/2.html', '/redirect/3.html');
      // server.setRedirect('/redirect/3.html', server.EMPTY_PAGE);
      const response = (await page.goto(server.PREFIX + '/redirect/1.html'))!;
      expect(response.ok()).toBe(true);
      expect(response.url()).toBe(server.EMPTY_PAGE);
    });

Comment 1

[Julian Descottes [:jdescottes]]

I don't think those errors are related to this issue, and this bug is most likely a duplicate of Bug 1852891.
Basically some times you will see the aborted errors because we attempt to emit events before the redirect, but they are still followed by the correct events. Example:

0:07.45 pid:2252 1695298499917	RemoteAgent	DEBUG	WebDriverBiDiConnection fb13a5c8-c719-4e0a-8773-af4a5c7edce7 <- {"type":"event","method":"script.realmDestroyed","params":{"realm":"ac2a8d27-d7c3-4f9b-84b4-67abf4f18532"}}
 0:07.45 pid:2252 console.error:
 0:07.45 pid:2252   InvalidStateError: JSWindowActorChild.sendAsyncMessage: JSWindowActorChild cannot send at the moment: _onRegistryEvent@chrome://remote/content/shared/messagehandler/transports/js-window-actors/MessageHandlerFrameChild.sys.mjs:101:10
 0:07.45 pid:2252 emit@resource://gre/modules/EventEmitter.sys.mjs:154:20
 0:07.45 pid:2252 _onMessageHandlerEvent@chrome://remote/content/shared/messagehandler/MessageHandlerRegistry.sys.mjs:234:10
 0:07.45 pid:2252 emit@resource://gre/modules/EventEmitter.sys.mjs:154:20
 0:07.45 pid:2252 emitEvent@chrome://remote/content/shared/messagehandler/MessageHandler.sys.mjs:178:10
 0:07.45 pid:2252 emitEvent@chrome://remote/content/shared/messagehandler/Module.sys.mjs:54:25
 0:07.45 pid:2252 #onDOMContentLoaded@chrome://remote/content/webdriver-bidi/modules/windowglobal/browsingContext.sys.mjs:105:12
 0:07.45 pid:2252 emit@resource://gre/modules/EventEmitter.sys.mjs:154:20
 0:07.45 pid:2252 #onDOMContentLoaded@chrome://remote/content/shared/listeners/LoadListener.sys.mjs:92:12
 0:07.45 pid:2252 
 0:07.45 pid:2252 console.error:
 0:07.45 pid:2252   InvalidStateError: JSWindowActorChild.sendAsyncMessage: JSWindowActorChild cannot send at the moment: _onRegistryEvent@chrome://remote/content/shared/messagehandler/transports/js-window-actors/MessageHandlerFrameChild.sys.mjs:101:10
 0:07.45 pid:2252 emit@resource://gre/modules/EventEmitter.sys.mjs:154:20
 0:07.45 pid:2252 _onMessageHandlerEvent@chrome://remote/content/shared/messagehandler/MessageHandlerRegistry.sys.mjs:234:10
 0:07.45 pid:2252 emit@resource://gre/modules/EventEmitter.sys.mjs:154:20
 0:07.45 pid:2252 emitEvent@chrome://remote/content/shared/messagehandler/MessageHandler.sys.mjs:178:10
 0:07.45 pid:2252 emitEvent@chrome://remote/content/shared/messagehandler/Module.sys.mjs:54:25
 0:07.45 pid:2252 #onLoad@chrome://remote/content/webdriver-bidi/modules/windowglobal/browsingContext.sys.mjs:114:12
 0:07.45 pid:2252 emit@resource://gre/modules/EventEmitter.sys.mjs:154:20
 0:07.45 pid:2252 #onLoad@chrome://remote/content/shared/listeners/LoadListener.sys.mjs:100:12
 0:07.45 pid:2252 
 0:07.45 pid:2252 1695298499926	RemoteAgent	DEBUG	WebDriverBiDiConnection fb13a5c8-c719-4e0a-8773-af4a5c7edce7 <- {"type":"event","method":"browsingContext.domContentLoaded","params":{"context":"6c5a00f0-7750-49f1-a5db-708f9f7cb19d","timestamp":1695298499921,"url":"http://localhost:55275/empty.html","navigation":"71421465-e1c5-4b2a-8334-b1fdf04d62e4"}}
 0:07.45 pid:2252 1695298499926	RemoteAgent	DEBUG	WebDriverBiDiConnection fb13a5c8-c719-4e0a-8773-af4a5c7edce7 <- {"type":"event","method":"browsingContext.load","params":{"context":"6c5a00f0-7750-49f1-a5db-708f9f7cb19d","timestamp":1695298499921,"url":"http://localhost:55275/empty.html","navigation":"71421465-e1c5-4b2a-8334-b1fdf04d62e4"}}

So the problem here is that in case of redirects, it seems that we emit responseCompleted after the domContentLoaded and load events, and also after browsingContext.navigate resolved. And the puppeteer logic has a strong assumption on that order. Basically when navigate resolves, they immediately query a map which is filled only when the corresponding responseCompleted event has been received. I discussed this a bit with them and it's not something they want to make more flexible so we will have to find a way to fix the event order.

As I said in the other bug, so far I don't really know why we emit responseCompleted late in those scenarios.

Should we close as dupe?

Comment 2

[Julian Descottes [:jdescottes]]

First investigation was wrong. The issue here is that for redirects we have two sets of network events:

• one set for the /redirect/1.html request, which will end with a 302 status
• one set for the empty.html request, which will end with a 200 status

Both events contain the same navigation id, which confuses the puppeteer logic around here https://searchfox.org/mozilla-central/rev/077fc34d03b85b09add26b5f99f1a3a3a72c8720/remote/test/puppeteer/packages/puppeteer-core/src/common/bidi/NetworkManager.ts#76-92

Basically the 302 responseCompleted event is treated as the end of the navigation by puppeteer, which records 302 as the final status for this navigation.

Not sure exactly where this should be fixed. One question is whether a redirect should be treated as 2 (or more?) navigations with distinct navigation ids. I don't feel like this is right but maybe.

Otherwise should we drop the navigation id from network events as soon as we detect that a redirect will happen? That would be odd because we have no way to do that for the earlier event (beforeRequestSent).

Or maybe it's an issue with unexpected event ordering again. For redirected requests the usual order we have in Firefox is beforeRequestSent (original) > responseStarted (original) > beforeRequestSent (redirect) > responseStarted (redirect) > responseCompleted (original) > responseCompleted (redirect). I imagine that if all the events for the original request were emitted before we emit the ones for the redirect it would probably fix the issue?

Would be interesting to see which events chrome emits.

Comment 3

[Julian Descottes [:jdescottes]]

There is the same issue with Chrome + BiDi, so it really sounds like a bug in the puppeteer logic.
Given that redirected requests have the same request.request id, and only a different redirect count, we should be careful to only clear the navigation map when we received the responseCompleted for the last known redirect count.

Comment 4

[BugBot [:suhaib / :marco/ :calixte]]

The severity field is not set for this bug.
:whimboo, could you have a look please?

For more information, please visit BugBot documentation.

Comment 5

[Julian Descottes [:jdescottes]]

Check if issue was filed on puppeteer side

Comment 6

[Henrik Skupin [:whimboo][⌚️UTC+2]]

This can be seen as well when running the integration tests for pdf.js:

console.error: 
  InvalidStateError: JSWindowActorChild.sendAsyncMessage: JSWindowActorChild cannot send at the moment: _onRegistryEvent@chrome://remote/content/shared/messagehandler/transports/js-window-actors/MessageHandlerFrameChild.sys.mjs:101:10
emit@resource://gre/modules/EventEmitter.sys.mjs:154:20
_onMessageHandlerEvent@chrome://remote/content/shared/messagehandler/MessageHandlerRegistry.sys.mjs:234:10
emit@resource://gre/modules/EventEmitter.sys.mjs:154:20
emitEvent@chrome://remote/content/shared/messagehandler/MessageHandler.sys.mjs:178:10
emitEvent@chrome://remote/content/shared/messagehandler/Module.sys.mjs:54:25
#onDOMContentLoaded@chrome://remote/content/webdriver-bidi/modules/windowglobal/browsingContext.sys.mjs:105:12
emit@resource://gre/modules/EventEmitter.sys.mjs:154:20
#onDOMContentLoaded@chrome://remote/content/shared/listeners/LoadListener.sys.mjs:92:12

Comment 7

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Not that this problem actually went away with the fixes in the pdf.js tests so that commands that not yet returned a reply will not fail when the test times out and the next test page is loaded. So it's basically not hard-blocking bug 1860992 anymore.