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

[task 2022-09-07T12:24:28.175Z] 12:24:28     INFO - TEST-PASS | /webdriver/tests/bidi/script/evaluate/sandbox.py | test_sandbox 
[task 2022-09-07T12:24:28.175Z] 12:24:28     INFO - TEST-UNEXPECTED-FAIL | /webdriver/tests/bidi/script/evaluate/sandbox.py | test_sandbox_with_empty_name - webdriver.bidi.error.UnknownErrorException: unknown error (AbortError: Actor 'MessageHandlerFrame' destroyed before query 'MessageHandlerFrameParent:sendCommand' was resolved)
[task 2022-09-07T12:24:28.175Z] 12:24:28     INFO - bidi_session = <webdriver.bidi.client.BidiSession object at 0x00000297419FEB50>
[task 2022-09-07T12:24:28.175Z] 12:24:28     INFO - new_tab = {'context': '848e2e2e-e803-4be6-a221-5911cfb3e7c2'}
[task 2022-09-07T12:24:28.175Z] 12:24:28     INFO - 
[task 2022-09-07T12:24:28.175Z] 12:24:28     INFO -     @pytest.mark.asyncio
[task 2022-09-07T12:24:28.175Z] 12:24:28     INFO -     async def test_sandbox_with_empty_name(bidi_session, new_tab):
[task 2022-09-07T12:24:28.175Z] 12:24:28     INFO -         # BiDi specification doesn't have restrictions of a sandbox name,
[task 2022-09-07T12:24:28.175Z] 12:24:28     INFO -         # that's why we want to make sure that it works with an empty name
[task 2022-09-07T12:24:28.175Z] 12:24:28     INFO -         await bidi_session.script.evaluate(
[task 2022-09-07T12:24:28.175Z] 12:24:28     INFO -             expression="window.foo = 'bar'",
[task 2022-09-07T12:24:28.176Z] 12:24:28     INFO -             target=ContextTarget(new_tab["context"], ""),
[task 2022-09-07T12:24:28.176Z] 12:24:28     INFO -             await_promise=True,
[task 2022-09-07T12:24:28.176Z] 12:24:28     INFO -         )
[task 2022-09-07T12:24:28.176Z] 12:24:28     INFO -     
[task 2022-09-07T12:24:28.176Z] 12:24:28     INFO -         # Make sure that we can find the sandbox with the empty name
[task 2022-09-07T12:24:28.176Z] 12:24:28     INFO - >       result = await bidi_session.script.evaluate(
[task 2022-09-07T12:24:28.176Z] 12:24:28     INFO -             expression="window.foo",
[task 2022-09-07T12:24:28.176Z] 12:24:28     INFO -             target=ContextTarget(new_tab["context"], ""),
[task 2022-09-07T12:24:28.176Z] 12:24:28     INFO -             await_promise=True,
[task 2022-09-07T12:24:28.176Z] 12:24:28     INFO -         )
[task 2022-09-07T12:24:28.176Z] 12:24:28     INFO - 
[task 2022-09-07T12:24:28.177Z] 12:24:28     INFO - bidi_session = <webdriver.bidi.client.BidiSession object at 0x00000297419FEB50>
[task 2022-09-07T12:24:28.177Z] 12:24:28     INFO - new_tab    = {'context': '848e2e2e-e803-4be6-a221-5911cfb3e7c2'}
[task 2022-09-07T12:24:28.177Z] 12:24:28     INFO - 
[task 2022-09-07T12:24:28.177Z] 12:24:28     INFO - tests\web-platform\tests\webdriver\tests\bidi\script\evaluate\sandbox.py:61: 
[task 2022-09-07T12:24:28.178Z] 12:24:28     INFO - _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
[task 2022-09-07T12:24:28.178Z] 12:24:28     INFO - 
[task 2022-09-07T12:24:28.178Z] 12:24:28     INFO - self = <webdriver.bidi.modules.script.Script object at 0x00000297419FEC10>
[task 2022-09-07T12:24:28.178Z] 12:24:28     INFO - kwargs = {'await_promise': True, 'expression': 'window.foo', 'target': {'context': '848e2e2e-e803-4be6-a221-5911cfb3e7c2', 'sandbox': ''}}
[task 2022-09-07T12:24:28.178Z] 12:24:28     INFO - params = {'awaitPromise': True, 'expression': 'window.foo', 'target': {'context': '848e2e2e-e803-4be6-a221-5911cfb3e7c2', 'sandbox': ''}}
[task 2022-09-07T12:24:28.178Z] 12:24:28     INFO - mod_name = 'script', cmd_name = 'script.evaluate'
[task 2022-09-07T12:24:28.178Z] 12:24:28     INFO - future = <Future finished exception=UnknownErrorException(unknown error, AbortError: Actor 'MessageHandlerFrame' destroyed before query 'MessageHandlerFrameParent:sendCommand' was resolved, )>
[task 2022-09-07T12:24:28.178Z] 12:24:28     INFO - 
[task 2022-09-07T12:24:28.178Z] 12:24:28     INFO -     @functools.wraps(params_fn)
[task 2022-09-07T12:24:28.178Z] 12:24:28     INFO -     async def inner(self: Any, **kwargs: Any) -> Any:
[task 2022-09-07T12:24:28.178Z] 12:24:28     INFO -         params = params_fn(self, **kwargs)
[task 2022-09-07T12:24:28.178Z] 12:24:28     INFO -     
[task 2022-09-07T12:24:28.178Z] 12:24:28     INFO -         # Convert the classname and the method name to a bidi command name
[task 2022-09-07T12:24:28.178Z] 12:24:28     INFO -         mod_name = owner.__name__[0].lower() + owner.__name__[1:]
[task 2022-09-07T12:24:28.178Z] 12:24:28     INFO -         if hasattr(owner, "prefix"):
[task 2022-09-07T12:24:28.178Z] 12:24:28     INFO -             mod_name = f"{owner.prefix}:{mod_name}"
[task 2022-09-07T12:24:28.178Z] 12:24:28     INFO -         cmd_name = f"{mod_name}.{to_camelcase(name)}"
[task 2022-09-07T12:24:28.179Z] 12:24:28     INFO -     
[task 2022-09-07T12:24:28.179Z] 12:24:28     INFO -         future = await self.session.send_command(cmd_name, params)
[task 2022-09-07T12:24:28.179Z] 12:24:28     INFO - >       result = await future
[task 2022-09-07T12:24:28.179Z] 12:24:28     INFO - E       webdriver.bidi.error.UnknownErrorException: unknown error (AbortError: Actor 'MessageHandlerFrame' destroyed before query 'MessageHandlerFrameParent:sendCommand' was resolved)
[task 2022-09-07T12:24:28.179Z] 12:24:28     INFO - 
[task 2022-09-07T12:24:28.179Z] 12:24:28     INFO - cmd_name   = 'script.evaluate'
[task 2022-09-07T12:24:28.179Z] 12:24:28     INFO - future     = <Future finished exception=UnknownErrorException(unknown error, AbortError: Actor 'MessageHandlerFrame' destroyed before query 'MessageHandlerFrameParent:sendCommand' was resolved, )>
[task 2022-09-07T12:24:28.179Z] 12:24:28     INFO - kwargs     = {'await_promise': True,
[task 2022-09-07T12:24:28.179Z] 12:24:28     INFO -  'expression': 'window.foo',
[task 2022-09-07T12:24:28.179Z] 12:24:28     INFO -  'target': {'context': '848e2e2e-e803-4be6-a221-5911cfb3e7c2', 'sandbox': ''}}
[task 2022-09-07T12:24:28.179Z] 12:24:28     INFO - mod_name   = 'script'
[task 2022-09-07T12:24:28.179Z] 12:24:28     INFO - name       = 'evaluate'
[task 2022-09-07T12:24:28.180Z] 12:24:28     INFO - owner      = <class 'webdriver.bidi.modules.script.Script'>
[task 2022-09-07T12:24:28.180Z] 12:24:28     INFO - params     = {'awaitPromise': True,
[task 2022-09-07T12:24:28.180Z] 12:24:28     INFO -  'expression': 'window.foo',
[task 2022-09-07T12:24:28.180Z] 12:24:28     INFO -  'target': {'context': '848e2e2e-e803-4be6-a221-5911cfb3e7c2', 'sandbox': ''}}
[task 2022-09-07T12:24:28.180Z] 12:24:28     INFO - params_fn  = <function Script.evaluate at 0x000002973EDA5DC0>
[task 2022-09-07T12:24:28.180Z] 12:24:28     INFO - result_fn  = <function Script._evaluate at 0x000002973EDA5E50>
[task 2022-09-07T12:24:28.180Z] 12:24:28     INFO - self       = <webdriver.bidi.modules.script.Script object at 0x00000297419FEC10>
[task 2022-09-07T12:24:28.180Z] 12:24:28     INFO - 
[task 2022-09-07T12:24:28.180Z] 12:24:28     INFO - tests\web-platform\tests\tools\webdriver\webdriver\bidi\modules\_module.py:62: UnknownErrorException
[task 2022-09-07T12:24:28.182Z] 12:24:28     INFO - ....
[task 2022-09-07T12:24:28.182Z] 12:24:28     INFO - TEST-OK | /webdriver/tests/bidi/script/evaluate/sandbox.py | took 6861ms

https://treeherder.mozilla.org/logviewer?job_id=389735688&repo=autoland&lineNumber=79224-79236

[task 2022-09-07T12:24:25.734Z] 12:24:25     INFO - PID 2276 | 1662553465730	WebDriver BiDi	DEBUG	e69318c2-50b5-470e-9fc6-1d6dbfd7c2d4 -> {"id":9,"method":"script.evaluate","params":{"expression":"window.foo = 'bar'","target":{"context":"848e2e2e-e803-4be6-a221-5911cfb3e7c2","sandbox":""},"awaitPromise":true}}
[task 2022-09-07T12:24:25.736Z] 12:24:25     INFO - PID 2276 | 1662553465730	RemoteAgent	TRACE	Received command script.evaluate for destination ROOT
[task 2022-09-07T12:24:25.791Z] 12:24:25     INFO - PID 2276 | 1662553465795	RemoteAgent	TRACE	Created MessageHandler WINDOW_GLOBAL for session e69318c2-50b5-470e-9fc6-1d6dbfd7c2d4
[task 2022-09-07T12:24:25.801Z] 12:24:25     INFO - PID 2276 | 1662553465795	RemoteAgent	TRACE	Received command script.evaluateExpression for destination WINDOW_GLOBAL
[task 2022-09-07T12:24:25.805Z] 12:24:25     INFO - PID 2276 | 1662553465802	RemoteAgent	TRACE	Module windowglobal/script.jsm found for WINDOW_GLOBAL
[task 2022-09-07T12:24:25.812Z] 12:24:25     INFO - PID 2276 | 1662553465808	WebDriver BiDi	DEBUG	e69318c2-50b5-470e-9fc6-1d6dbfd7c2d4 <- {"id":9,"result":{"realm":"8867c690-681b-4e2d-9b30-f0a6e3f98e6c","result":{"type":"string","value":"bar"}}}
[task 2022-09-07T12:24:25.816Z] 12:24:25     INFO - PID 2276 | 1662553465812	WebDriver BiDi	DEBUG	e69318c2-50b5-470e-9fc6-1d6dbfd7c2d4 -> {"id":10,"method":"script.evaluate","params":{"expression":"window.foo","target":{"context":"848e2e2e-e803-4be6-a221-5911cfb3e7c2","sandbox":""},"awaitPromise":true}}
[task 2022-09-07T12:24:25.817Z] 12:24:25     INFO - PID 2276 | 1662553465813	RemoteAgent	TRACE	Received command script.evaluate for destination ROOT
[task 2022-09-07T12:24:25.820Z] 12:24:25     INFO - PID 2276 | 1662553465817	WebDriver BiDi	DEBUG	e69318c2-50b5-470e-9fc6-1d6dbfd7c2d4 <- {"id":10,"error":"unknown error","message":"AbortError: Actor 'MessageHandlerFrame' destroyed before query 'MessageHandlerFrameParent:sendCommand' was resolved","stacktrace":""}
[task 2022-09-07T12:24:25.829Z] 12:24:25     INFO - PID 2276 | 1662553465827	RemoteAgent	TRACE	Received command script.evaluateExpression for destination WINDOW_GLOBAL
[task 2022-09-07T12:24:25.832Z] 12:24:25     INFO - PID 2276 | 1662553465830	WebDriver BiDi	WARN	Unsupported type: object for remote value: SecurityError: Permission denied to access property "foo" on cross-origin object
[task 2022-09-07T12:24:25.835Z] 12:24:25     INFO - PID 2276 | 1662553465832	RemoteAgent	TRACE	MessageHandler WINDOW_GLOBAL for session e69318c2-50b5-470e-9fc6-1d6dbfd7c2d4 is being destroyed
[task 2022-09-07T12:24:25.836Z] 12:24:25     INFO - PID 2276 | 1662553465832	RemoteAgent	TRACE	Unregistered MessageHandler WINDOW_GLOBAL for session e69318c2-50b5-470e-9fc6-1d6dbfd7c2d4
[task 2022-09-07T12:24:25.852Z] 12:24:25     INFO - STDOUT: FAILED

That's suspicious. This specific test does not navigate at all. So why is the JSWindowActor destroyed?

The failure happened only once so far so maybe we should keep an eye on it for now.

We might still be missing a few logs in our progress listener to investigate this efficiently. We have the following logs for the test that fails:

[task 2022-09-07T12:24:25.474Z] 12:24:25     INFO - PID 2276 | 1662553465475  WebDriver BiDi  DEBUG e69318c2-50b5-470e-9fc6-1d6dbfd7c2d4 -> {"id":8,"method":"browsingContext.create","params":{"type":"tab"}}
[task 2022-09-07T12:24:25.479Z] 12:24:25     INFO - PID 2276 | 1662553465476  RemoteAgent TRACE Received command browsingContext.create for destination ROOT
[task 2022-09-07T12:24:25.721Z] 12:24:25     INFO - PID 2276 | 1662553465723  RemoteAgent TRACE [12] No navigation detected: about:blank
[task 2022-09-07T12:24:25.727Z] 12:24:25     INFO - PID 2276 | 1662553465724  WebDriver BiDi  DEBUG e69318c2-50b5-470e-9fc6-1d6dbfd7c2d4 <- {"id":8,"result":{"context":"848e2e2e-e803-4be6-a221-5911cfb3e7c2"}}

The TRACE [12] No navigation detected: about:blank is related to the waitForInitialWindow done when we create new browsing contexts. In this case we are on a regular platform (opt, no asan/tsan/ccov... but it's android) so we use a 200ms delay before we assume the navigation will not happen/already happened. And then in the logs we can see the query is cancelled from the parent process, but we still receive the command in the content process and attempt to execute it, where it fails with a cross origin error when trying to access foo.

So I think we are not waiting long enough for the new tab to be ready here. Maybe we should increase the delay slightly for Android?

Edit: somehow I though this was android only, but the failure from which I took the logs was windows. Maybe 200ms is too short overall?