Filed by: mlaza [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=377451313&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/RHlDP6bdQH6cq-MGqhtD6g/runs/0/artifacts/public/logs/live_backing.log

[task 2022-05-09T21:06:50.810Z] 21:06:50     INFO - STDOUT: =================================== FAILURES ===================================
[task 2022-05-09T21:06:50.810Z] 21:06:50     INFO - STDOUT: ________________________________ test_type[tab] ________________________________
[task 2022-05-09T21:06:50.811Z] 21:06:50     INFO - STDOUT: bidi_session = <webdriver.bidi.client.BidiSession object at 0x7fa1cc4bbdd8>
[task 2022-05-09T21:06:50.811Z] 21:06:50     INFO - STDOUT: current_session = <Session b57f49e2-47e3-4191-94d8-0e62ee823e4c>
[task 2022-05-09T21:06:50.811Z] 21:06:50     INFO - STDOUT: wait_for_event = <function wait_for_event.<locals>.wait_for_event at 0x7fa1cc4d9488>
[task 2022-05-09T21:06:50.811Z] 21:06:50     INFO - STDOUT: value = 'tab'
[task 2022-05-09T21:06:50.811Z] 21:06:50     INFO - STDOUT:     @pytest.mark.parametrize("value", ["tab", "window"])
[task 2022-05-09T21:06:50.811Z] 21:06:50     INFO - STDOUT:     async def test_type(bidi_session, current_session, wait_for_event, value):
[task 2022-05-09T21:06:50.811Z] 21:06:50     INFO - STDOUT:         contexts = await bidi_session.browsing_context.get_tree(max_depth=0)
[task 2022-05-09T21:06:50.811Z] 21:06:50     INFO - STDOUT:         assert len(contexts) == 1
[task 2022-05-09T21:06:50.815Z] 21:06:50     INFO - 
[task 2022-05-09T21:06:50.815Z] 21:06:50     INFO - TEST-UNEXPECTED-FAIL | /webdriver/tests/bidi/browsing_context/create/type.py | test_type[tab] - assert None is False
[task 2022-05-09T21:06:50.815Z] 21:06:50     INFO - bidi_session = <webdriver.bidi.client.BidiSession object at 0x7fa1cc4bbdd8>
[task 2022-05-09T21:06:50.815Z] 21:06:50     INFO - current_session = <Session b57f49e2-47e3-4191-94d8-0e62ee823e4c>
[task 2022-05-09T21:06:50.815Z] 21:06:50     INFO - wait_for_event = <function wait_for_event.<locals>.wait_for_event at 0x7fa1cc4d9488>
[task 2022-05-09T21:06:50.815Z] 21:06:50     INFO - value = 'tab'
[task 2022-05-09T21:06:50.815Z] 21:06:50     INFO - 
[task 2022-05-09T21:06:50.815Z] 21:06:50     INFO -     @pytest.mark.parametrize("value", ["tab", "window"])
[task 2022-05-09T21:06:50.815Z] 21:06:50     INFO -     async def test_type(bidi_session, current_session, wait_for_event, value):
[task 2022-05-09T21:06:50.815Z] 21:06:50     INFO -         contexts = await bidi_session.browsing_context.get_tree(max_depth=0)
[task 2022-05-09T21:06:50.815Z] 21:06:50     INFO -         assert len(contexts) == 1
[task 2022-05-09T21:06:50.815Z] 21:06:50     INFO -     
[task 2022-05-09T21:06:50.815Z] 21:06:50     INFO -         new_context_id = await bidi_session.browsing_context.create(type_hint=value)
[task 2022-05-09T21:06:50.815Z] 21:06:50     INFO -         assert contexts[0]["context"] != new_context_id
[task 2022-05-09T21:06:50.815Z] 21:06:50     INFO -     
[task 2022-05-09T21:06:50.815Z] 21:06:50     INFO -         # Check there is an additional browsing context
[task 2022-05-09T21:06:50.815Z] 21:06:50     INFO -         contexts = await bidi_session.browsing_context.get_tree(max_depth=0)
[task 2022-05-09T21:06:50.815Z] 21:06:50     INFO -         assert len(contexts) == 2
[task 2022-05-09T21:06:50.815Z] 21:06:50     INFO -     
[task 2022-05-09T21:06:50.815Z] 21:06:50     INFO -         # Retrieve the new context info
[task 2022-05-09T21:06:50.815Z] 21:06:50     INFO -         contexts = await bidi_session.browsing_context.get_tree(
[task 2022-05-09T21:06:50.815Z] 21:06:50     INFO -             max_depth=0, root=new_context_id
[task 2022-05-09T21:06:50.815Z] 21:06:50     INFO -         )
[task 2022-05-09T21:06:50.815Z] 21:06:50     INFO -     
[task 2022-05-09T21:06:50.815Z] 21:06:50     INFO -         assert_browsing_context(
[task 2022-05-09T21:06:50.815Z] 21:06:50     INFO -             contexts[0],
[task 2022-05-09T21:06:50.815Z] 21:06:50     INFO -             new_context_id,
[task 2022-05-09T21:06:50.815Z] 21:06:50     INFO -             children=None,
[task 2022-05-09T21:06:50.816Z] 21:06:50     INFO -             is_root=True,
[task 2022-05-09T21:06:50.816Z] 21:06:50     INFO -             parent=None,
[task 2022-05-09T21:06:50.816Z] 21:06:50     INFO -             url="about:blank",
[task 2022-05-09T21:06:50.816Z] 21:06:50     INFO -         )
[task 2022-05-09T21:06:50.816Z] 21:06:50     INFO -     
[task 2022-05-09T21:06:50.816Z] 21:06:50     INFO -         # Fallback to WebDriver HTTP to check that the new context has no opener.
[task 2022-05-09T21:06:50.816Z] 21:06:50     INFO -         initial_window = current_session.window_handle
[task 2022-05-09T21:06:50.816Z] 21:06:50     INFO -         current_session.window_handle = new_context_id
[task 2022-05-09T21:06:50.816Z] 21:06:50     INFO -     
[task 2022-05-09T21:06:50.816Z] 21:06:50     INFO -         try:
[task 2022-05-09T21:06:50.816Z] 21:06:50     INFO -             opener = current_session.execute_script("return !!window.opener;")
[task 2022-05-09T21:06:50.816Z] 21:06:50     INFO - >           assert opener is False
[task 2022-05-09T21:06:50.816Z] 21:06:50     INFO - E           assert None is False[task 2022-05-09T21:06:50.816Z] 21:06:50     INFO - 
[task 2022-05-09T21:06:50.816Z] 21:06:50     INFO - bidi_session = <webdriver.bidi.client.BidiSession object at 0x7fa1cc4bbdd8>
[task 2022-05-09T21:06:50.816Z] 21:06:50     INFO - contexts   = [{'children': None,
[task 2022-05-09T21:06:50.816Z] 21:06:50     INFO -   'context': '80554926-796c-4974-abf0-24d08f6a0b69',
[task 2022-05-09T21:06:50.816Z] 21:06:50     INFO -   'parent': None,
[task 2022-05-09T21:06:50.816Z] 21:06:50     INFO -   'url': 'about:blank'}]
[task 2022-05-09T21:06:50.816Z] 21:06:50     INFO - current_session = <Session b57f49e2-47e3-4191-94d8-0e62ee823e4c>
[task 2022-05-09T21:06:50.816Z] 21:06:50     INFO - initial_window = '799384a1-bae5-4e59-8b0f-dff952d8ec33'
[task 2022-05-09T21:06:50.816Z] 21:06:50     INFO - new_context_id = '80554926-796c-4974-abf0-24d08f6a0b69'
[task 2022-05-09T21:06:50.816Z] 21:06:50     INFO - opener     = None
[task 2022-05-09T21:06:50.816Z] 21:06:50     INFO - value      = 'tab'
[task 2022-05-09T21:06:50.816Z] 21:06:50     INFO - wait_for_event = <function wait_for_event.<locals>.wait_for_event at 0x7fa1cc4d9488>
[task 2022-05-09T21:06:50.816Z] 21:06:50     INFO - 
[task 2022-05-09T21:06:50.816Z] 21:06:50     INFO - tests/web-platform/tests/webdriver/tests/bidi/browsing_context/create/type.py:40: AssertionError
[task 2022-05-09T21:06:50.816Z] 21:06:50     INFO - .
[task 2022-05-09T21:06:50.816Z] 21:06:50     INFO - TEST-OK | /webdriver/tests/bidi/browsing_context/create/type.py | took 11658ms

This is a strange failure. I wonder why Execute Script can return null here at all when it should be a boolean:

[task 2022-05-09T21:06:44.578Z] 21:06:44     INFO - PID 1608 | 1652130404576	Marionette	DEBUG	0 -> [0,6,"WebDriver:ExecuteScript",{"args":[],"script":"return !!window.opener;"}]
[task 2022-05-09T21:06:44.584Z] 21:06:44     INFO - PID 1608 | 1652130404583	Marionette	DEBUG	0 <- [1,6,null,{"value":null}]

This is actually a Linux ASAN intermittent only.

As discussed, this is probably due to our retry logic around JSWindowActor's (see the blocking bug added above). The logs for a recent failure are compatible with this theory:

[task 2022-06-11T10:31:23.568Z] 10:31:23 INFO - PID 1631 | 1654943483566 RemoteAgent TRACE Received command browsingContext.create for destination ROOT
[task 2022-06-11T10:31:23.821Z] 10:31:23 INFO - PID 1631 | 1654943483819 RemoteAgent TRACE [27] No navigation detected: about:blank
[ ... ]
[task 2022-06-11T10:31:23.897Z] 10:31:23 INFO - PID 1631 | 1654943483896 Marionette DEBUG 0 -> [0,6,"WebDriver:ExecuteScript",{"args":[],"script":"return !!window.opener;"}]
[task 2022-06-11T10:31:23.908Z] 10:31:23 INFO - PID 1631 | 1654943483903 Marionette DEBUG 0 <- [1,6,null,{"value":null}]
[ ... ]
[task 2022-06-11T10:31:23.917Z] 10:31:23 INFO - PID 1631 | 1654943483916 Marionette TRACE [27] MarionetteCommands actor created for window id 25

Only kept relevant logs, but we create the tab, then we have a "No navigation detected", which most likely comes from the waitForInitialNavigationCompleted in browsingContext.create. After that we call script.execute which seems to return null almost immediately, and then only do we get a notification about MarionetteCommands actor creation.

Since this is ASAN only, it's very likely that increasing the timeout to wait for navigation could improve the situation.

(In reply to Julian Descottes [:jdescottes] from comment #8)

Since this is ASAN only, it's very likely that increasing the timeout to wait for navigation could improve the situation.

Bug 1767295 might help for this specific item.

Increasing the timeout seems to fix the intermittent. See those 2 try pushes, https://treeherder.mozilla.org/jobs?repo=try&author=jdescottes%40mozilla.com&tochange=fe6a90c00961348708ce4614ab0c1d56c6ae5aed&fromchange=9fb26eee7e663746b8905ca903b4459bdbe962af&selectedTaskRun=I8foddUdTZqEN3kpuYgbTQ.1

the first one has an increased navigation timeout from 200ms to 1000ms, the second one is a recent central baseline.

On bug 1773686 this has been changed to use the BiDi version of script.evaluate and as such this problem is gone.