1841125 - `browsingContext.create` fails after abandoned `browsingContext.print` via `browsingContext.close`

Status: NEW

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

Description

[Nik]

User Agent: Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/114.0.0.0 Safari/537.36

Steps to reproduce:

This happens in Puppeteer test as only:
Run Page.pdf -> should respect timeout as only.
And Page.title -> should return the page title
Relative code https://github.com/puppeteer/puppeteer/blob/main/test/src/page.spec.ts#L2096

Simple BiDi repo -> Send command in the following order:

1. Set up a page via BiDi
2. Send command to Print page
3. Send command to close the Browsing Context
4. Try to create a new Browsing Context

Actual results:

The command fails with
"error":"unknown error","message":"TypeError: can't access property \"addTab\", tabBrowser is undefined","stacktrace":"addTab@chrome://remote/content/shared/TabManager.sys.mjs:150:17\ncreate@chrome://remote/content/webdriver-bidi/modules/root/browsingContext.sys.mjs:247:43\nhandleCommand@chrome://remote/content/shared/messagehandler/MessageHandler.sys.mjs:257:33\nexecute@chrome://remote/content/shared/webdriver/Session.sys.mjs:252:32\nonPacket@chrome://remote/content/webdriver-bidi/WebDriverBiDiConnection.sys.mjs:193:37\nonMessage@chrome://remote/content/server/WebSocketTransport.sys.mjs:127:18\nhandleEvent@chrome://remote/content/server/WebSocketTransport.sys.mjs:109:14\n"

Note: calling the BrowsingContext.create after this will work.

Expected results:

The command should work.

Comment 1

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

I can run that test without problems with a recent Nightly build of Firefox. Would you mind also attaching a trace log as created when the remote.log.level preference is set to Trace? That would be kinda helpful.

Comment 2

[Nik]

Attachment: TestSetUp

Comment 3

[Nik]

Attachment: firefox-bidi-linux.txt

Logs with Trace and puppeteer:webDriverBiDi:* debugging

Comment 4

[Nik]

It seems this is passing on CI sometimes. It looks to be some timing thing.
If you manually add a delay ( 50ms under that it start to be flaky ) before the second getTimeState() (This creates delete the old page and creates a new one) line the test will pass.

Comment 5

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

Note that the logs indicate a race when trying to get the initial set of contexts via browsingContext.getTree:

2023-06-29T21:19:06.927Z puppeteer:webDriverBiDi:SEND ► [ '{"id":3,"method":"browsingContext.getTree","params":{}}' ]
2023-06-29T21:19:06.927Z puppeteer:webDriverBiDi:SEND ► [
  '{"id":4,"method":"browsingContext.create","params":{"type":"tab"}}'
]

Why don't you await the getTree command before trying to create a new tab?

The same seems to apply to the print command:

1688073547055	RemoteAgent	DEBUG	WebDriverBiDiConnection bbb4760e-3671-4ce4-9723-58c49a17b6ac -> {"id":8,"method":"browsingContext.print","params":{"context":"6732f99e-85fc-4718-b7e3-3027d2d9cfd0","background":false,"margin":{"top":0,"left":0,"bottom":0,"right":0},"orientation":"portrait","page":{"width":8.5,"height":11},"pageRanges":[""],"scale":1,"shrinkToFit":true}}
1688073547055	RemoteAgent	TRACE	Module root/browsingContext.sys.mjs found for ROOT
1688073547055	RemoteAgent	TRACE	Received command browsingContext.print for destination ROOT
1688073547055	RemoteAgent	TRACE	Module root/browsingContext.sys.mjs found for ROOT
1688073547062	RemoteAgent	DEBUG	Got page ranges [1, 2147483647]
1688073547064	RemoteAgent	DEBUG	WebDriverBiDiConnection bbb4760e-3671-4ce4-9723-58c49a17b6ac -> {"id":9,"method":"browsingContext.close","params":{"context":"6732f99e-85fc-4718-b7e3-3027d2d9cfd0"}}
1688073547064	RemoteAgent	TRACE	Module root/browsingContext.sys.mjs found for ROOT
1688073547064	RemoteAgent	TRACE	Received command browsingContext.close for destination ROOT
1688073547064	RemoteAgent	TRACE	Module root/browsingContext.sys.mjs found for ROOT
1688073547070	RemoteAgent	DEBUG	WebDriverBiDiConnection bbb4760e-3671-4ce4-9723-58c49a17b6ac <- {"id":9,"result":{}}
1688073547070	RemoteAgent	TRACE	MessageHandler WINDOW_GLOBAL for session d64c10ca-884b-48f8-9b73-6667e9308fe5 is being destroyed
1688073547070	RemoteAgent	TRACE	Unregistered MessageHandler WINDOW_GLOBAL for session d64c10ca-884b-48f8-9b73-6667e9308fe5
2023-06-29T21:19:07.070Z puppeteer:webDriverBiDi:RECV ◀ [ '{"id":9,"result":{}}' ]
[..]
1688073547082	RemoteAgent	DEBUG	WebDriverBiDiConnection bbb4760e-3671-4ce4-9723-58c49a17b6ac -> {"id":10,"method":"browsingContext.create","params":{"type":"tab"}}
1688073547082	RemoteAgent	TRACE	Module root/browsingContext.sys.mjs found for ROOT
1688073547082	RemoteAgent	TRACE	Received command browsingContext.create for destination ROOT
1688073547082	RemoteAgent	TRACE	Module root/browsingContext.sys.mjs found for ROOT
1688073547082	RemoteAgent	DEBUG	WebDriverBiDiConnection bbb4760e-3671-4ce4-9723-58c49a17b6ac <- {"id":10,"error":"unknown error","message":"TypeError: can't access property \"addTab\", tabBrowser is undefined","stacktrace":"addTab@chrome://remote/content/shared/TabManager.sys.mjs:150:17\ncreate@chrome://remote/content/webdriver-bidi/modules/root/br ... ontent/server/WebSocketTransport.sys.mjs:127:18\nhandleEvent@chrome://remote/content/server/WebSocketTransport.sys.mjs:109:14\n"}

What's interesting here is that I can reproduce this now with a wdspec test but only for the print command so far. Here is how it has to look like:

async def test(bidi_session, inline, wait_response=False):
    new_tab = await bidi_session.browsing_context.create(type_hint='tab')

    page = inline("""<div>foo</div""")
    await bidi_session.browsing_context.navigate(
        context=new_tab["context"], url=page, wait="complete")

    if wait_response:
        await bidi_session.browsing_context.print(context=new_tab["context"])
    else:
        await bidi_session.send_command("browsingContext.print", {
            "context": new_tab["context"],
        })

    await bidi_session.browsing_context.close(context=new_tab["context"])
    await bidi_session.browsing_context.create(type_hint="tab")

It can only be reproduced when the response of the print command is not awaited for and the tab that needs to be printed gets immediately removed. Also the failure happens in getTabBrowser(). While we have a valid win the gBrowser property is undefined. This is very strange and potentially could be a problem in Firefox. gBrowser should always be available for a browser window.

Comment 6

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

The problem here is actually the usage of Services.wm.getMostRecentWindow(). It returns a window which doesn't have a gBrowser object attached. Changing that to Services.wm.getMostRecentBrowserWindow() makes the test case above work. But when I add a sleep to the test I can see that instead of a tab a new window gets opened. As such I assume that we see a race here and check for gBrowser while the not-wanted new browser window hasn't been opened. I still don't understand why a new browser window is opened.

Comment 7

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

And when I spin the event loop right before (via setTimeout with 3ms) trying to get the gBrowser it works as well. Nevertheless we have to check why the new browser window is opened at all.

Comment 8

[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 9

[Julian Descottes [:jdescottes]]

Will investigate

Comment 10

[Julian Descottes [:jdescottes]]

I am also seeing a lot of errors related to this while working on the puppeteer sync for Bug 1842198.
For now I am going to SKIP the Page.pdf timeout test, because otherwise it makes randomly fail many other tests from page.spec.ts