Filed by: ccozmuta [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=376434410&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/Z73QCH2KTzKeOc6aS_NEbA/runs/0/artifacts/public/logs/live_backing.log
[task 2022-05-02T07:20:56.731Z] 07:20:56 INFO - TEST-START | /_mozilla/webdriver/bidi/interface/interface.py
[task 2022-05-02T07:20:57.320Z] 07:20:57 INFO - STDOUT: ============================= test session starts =============================
[task 2022-05-02T07:20:57.321Z] 07:20:57 INFO - STDOUT: platform win32 -- Python 3.9.5, pytest-6.1.1, py-1.5.2, pluggy-unknown -- Z:\task_165147427424097\build\venv\Scripts\python.exe
[task 2022-05-02T07:20:57.323Z] 07:20:57 INFO - STDOUT: rootdir: Z:\task_165147427424097\build
[task 2022-05-02T07:20:57.323Z] 07:20:57 INFO - STDOUT: plugins: asyncio-0.14.0
[task 2022-05-02T07:20:57.324Z] 07:20:57 INFO - STDOUT: collecting ...
[task 2022-05-02T07:20:57.353Z] 07:20:57 INFO - STDOUT: collected 1 item
[task 2022-05-02T07:20:57.358Z] 07:20:57 INFO - STDOUT: tests/web-platform/mozilla/tests/webdriver/bidi/interface/interface.py::test_navigator_webdriver_enabled
[task 2022-05-02T07:20:58.464Z] 07:20:58 INFO - STDOUT: *** You are running in headless mode.
[task 2022-05-02T07:20:58.504Z] 07:20:58 INFO - STDOUT: [Parent 2544, Main Thread] WARNING: Rejected attempt to change type of pref extensions.formautofill.creditCards.available's user value from bool to string: file /builds/worker/checkouts/gecko/modules/libpref/Preferences.cpp:1721
[task 2022-05-02T07:20:58.723Z] 07:20:58 INFO - STDOUT: 1651476058730 RemoteAgent DEBUG WebDriver BiDi enabled
[task 2022-05-02T07:20:58.731Z] 07:20:58 INFO - STDOUT: 1651476058730 RemoteAgent TRACE Received observer notification final-ui-startup
[task 2022-05-02T07:20:58.736Z] 07:20:58 INFO - STDOUT: 1651476058735 WebDriver BiDi DEBUG Awaiting all initial windows to be restored before enabling the protocol
[task 2022-05-02T07:20:59.155Z] 07:20:59 INFO - STDOUT: [2022-05-02T07:20:59Z WARN webrender::renderer] asking to enable_gpu_markers but no supporting extension was found
[task 2022-05-02T07:20:59.286Z] 07:20:59 INFO - STDOUT: [GFX1-]: RenderCompositorSWGL failed m[Parent 2544, Main Thread] WARNING: NS_ENSURE_TRUE(mPresShell) failed: file /builds/worker/checkouts/gecko/layout/generic/nsFrameSelection.cpp:1601
[task 2022-05-02T07:20:59.294Z] 07:20:59 INFO - STDOUT: apping default framebuffer, no dt
[task 2022-05-02T07:20:59.304Z] 07:20:59 INFO - STDOUT: [2022-05-02T07:20:59Z WARN webrender::device::gl] Cropping texture upload Box2D((0, 0), (0, 1)) to None
[task 2022-05-02T07:20:59.305Z] 07:20:59 INFO - STDOUT: [2022-05-02T07:20:59Z WARN webrender::device::gl] Cropping texture upload Box2D((0, 0), (0, 1)) to None
[task 2022-05-02T07:20:59.306Z] 07:20:59 INFO - STDOUT: [2022-05-02T07:20:59Z WARN webrender::device::gl] Cropping texture upload Box2D((0, 0), (0, 1)) to None
[task 2022-05-02T07:20:59.318Z] 07:20:59 INFO - STDOUT: [Parent 2544, Main Thread] WARNING: NS_ENSURE_TRUE(mPresShell) failed: file /builds/worker/checkouts/gecko/layout/generic/nsFrameSelection.cpp:1601
[task 2022-05-02T07:20:59.327Z] 07:20:59 INFO - STDOUT: [Parent 2544, Main Thread] WARNING: NS_ENSURE_TRUE(mPresShell) failed: file /builds/worker/checkouts/gecko/layout/generic/nsFrameSelection.cpp:1601
[task 2022-05-02T07:20:59.395Z] 07:20:59 INFO - STDOUT: 1651476059407 RemoteAgent TRACE Received observer notification sessionstore-windows-restored
[task 2022-05-02T07:20:59.421Z] 07:20:59 INFO - STDOUT: WebDriver BiDi listening on ws://localhost:54934
[task 2022-05-02T07:20:59.558Z] 07:20:59 INFO - STDOUT: [Parent 2544, Main Thread] WARNING: Failed to retarget HTML data delivery to the parser thread.: file /builds/worker/checkouts/gecko/parser/html/nsHtml5StreamParser.cpp:1234
[task 2022-05-02T07:20:59.564Z] 07:20:59 INFO - STDOUT: 1651476059563 RemoteAgent DEBUG WebDriverBiDiConnection 4d111f0a-6900-4909-9c5f-07228d47b5d9 accepted
[task 2022-05-02T07:20:59.573Z] 07:20:59 INFO - STDOUT: 1651476059572 WebDriver BiDi DEBUG no session -> {"id":1,"method":"session.new","params":{"capabilities":null}}
[task 2022-05-02T07:20:59.577Z] 07:20:59 INFO - STDOUT: 1651476059577 WebDriver BiDi DEBUG Connection 4d111f0a-6900-4909-9c5f-07228d47b5d9 attached to session c70761d5-9b88-47bc-b529-fd9cdf5aae3c
[task 2022-05-02T07:20:59.578Z] 07:20:59 INFO - STDOUT: 1651476059577 WebDriver BiDi DEBUG Registered session handler: /session/c70761d5-9b88-47bc-b529-fd9cdf5aae3c
[task 2022-05-02T07:20:59.579Z] 07:20:59 INFO - STDOUT: 1651476059578 WebDriver BiDi DEBUG c70761d5-9b88-47bc-b529-fd9cdf5aae3c <- {"id":1,"result":{"sessionId":"c70761d5-9b88-47bc-b529-fd9cdf5aae3c","capabilities":{"browserName":"firefox","browserVersion" ... tmpgeqljlny","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true,"proxy":{}}}}
[task 2022-05-02T07:20:59.588Z] 07:20:59 INFO - STDOUT: [2022-05-02T07:20:59Z WARN webrender::renderer] asking to enable_gpu_markers but no supporting extension was found
[task 2022-05-02T07:21:00.166Z] 07:21:00 INFO - STDOUT: Couldn't convert chrome URL: chrome://branding/locale/brand.properties
[task 2022-05-02T07:21:00.172Z] 07:21:00 INFO - STDOUT: [Child 7488, Main Thread] WARNING: Could not get the program name for a cubeb stream.: 'NS_SUCCEEDED(rv)', file /builds/worker/checkouts/gecko/dom/media/CubebUtils.cpp:413
[task 2022-05-02T07:21:00.173Z] 07:21:00 INFO - STDOUT: 1651476060169 WebDriver BiDi DEBUG c70761d5-9b88-47bc-b529-fd9cdf5aae3c -> {"id":2,"method":"session.subscribe","params":{"events":["log.entryAdded"]}}
[task 2022-05-02T07:21:00.181Z] 07:21:00 INFO - STDOUT: 1651476060180 RemoteAgent TRACE Registered MessageHandlerFrame actors
[task 2022-05-02T07:21:00.183Z] 07:21:00 INFO - STDOUT: 1651476060182 RemoteAgent TRACE Created MessageHandler ROOT for session c70761d5-9b88-47bc-b529-fd9cdf5aae3c
[task 2022-05-02T07:21:00.186Z] 07:21:00 INFO - STDOUT: 1651476060185 RemoteAgent TRACE Received command session.subscribe for destination ROOT
[task 2022-05-02T07:21:00.187Z] 07:21:00 INFO - STDOUT: 1651476060185 RemoteAgent TRACE Module root/session.jsm found for ROOT
[task 2022-05-02T07:21:00.188Z] 07:21:00 INFO - STDOUT: 1651476060186 RemoteAgent TRACE Received command log._subscribeEvent for destination ROOT
[task 2022-05-02T07:21:00.188Z] 07:21:00 INFO - STDOUT: 1651476060186 RemoteAgent TRACE Module root/log.jsm found for ROOT
[task 2022-05-02T07:21:00.194Z] 07:21:00 INFO - STDOUT: 1651476060189 RemoteAgent TRACE Received command log._applySessionData for destination WINDOW_GLOBAL
[task 2022-05-02T07:21:00.195Z] 07:21:00 INFO - STDOUT: 1651476060190 RemoteAgent TRACE Module windowglobal-in-root/log.jsm found for WINDOW_GLOBAL
[task 2022-05-02T07:21:00.207Z] 07:21:00 INFO - STDOUT: [2022-05-02T07:21:00Z WARN webrender::renderer] asking to enable_gpu_markers but no supporting extension was found
[task 2022-05-02T07:21:00.219Z] 07:21:00 INFO - STDOUT: 1651476060219 RemoteAgent TRACE Created MessageHandler WINDOW_GLOBAL for session c70761d5-9b88-47bc-b529-fd9cdf5aae3c
[task 2022-05-02T07:21:00.221Z] 07:21:00 INFO - STDOUT: 1651476060219 RemoteAgent TRACE Received command log._applySessionData for destination WINDOW_GLOBAL
[task 2022-05-02T07:21:00.226Z] 07:21:00 INFO - STDOUT: 1651476060225 RemoteAgent TRACE Module windowglobal/log.jsm found for WINDOW_GLOBAL
[task 2022-05-02T07:21:00.231Z] 07:21:00 INFO - STDOUT: 1651476060230 RemoteAgent TRACE MessageHandler WINDOW_GLOBAL for session c70761d5-9b88-47bc-b529-fd9cdf5aae3c is being destroyed
[task 2022-05-02T07:21:00.232Z] 07:21:00 INFO - STDOUT: 1651476060231 RemoteAgent TRACE Unregistered MessageHandler WINDOW_GLOBAL for session c70761d5-9b88-47bc-b529-fd9cdf5aae3c
[task 2022-05-02T07:21:00.242Z] 07:21:00 INFO - STDOUT: 1651476060240 WebDriver BiDi DEBUG c70761d5-9b88-47bc-b529-fd9cdf5aae3c <- {"id":2,"result":{}}
[task 2022-05-02T07:21:00.248Z] 07:21:00 INFO - STDOUT: 1651476060247 WebDriver BiDi DEBUG c70761d5-9b88-47bc-b529-fd9cdf5aae3c -> {"id":3,"method":"browsingContext.getTree","params":{"maxDepth":0}}
[task 2022-05-02T07:21:00.250Z] 07:21:00 INFO - STDOUT: 1651476060249 RemoteAgent TRACE Received command browsingContext.getTree for destination ROOT
[task 2022-05-02T07:21:00.251Z] 07:21:00 INFO - STDOUT: 1651476060250 RemoteAgent TRACE Module root/browsingContext.jsm found for ROOT
[task 2022-05-02T07:21:00.253Z] 07:21:00 INFO - STDOUT: 1651476060251 WebDriver BiDi DEBUG c70761d5-9b88-47bc-b529-fd9cdf5aae3c <- {"id":3,"result":{"contexts":[{"context":"424b3305-aa1a-47ce-8f2c-8f1dde4da9f8","url":"about:blank","children":null,"parent":null}]}}
[task 2022-05-02T07:21:00.254Z] 07:21:00 INFO - STDOUT: 1651476060253 RemoteAgent TRACE Received command log._applySessionData for destination WINDOW_GLOBAL
[task 2022-05-02T07:21:00.258Z] 07:21:00 INFO - STDOUT: 1651476060257 RemoteAgent TRACE Module windowglobal/log.jsm found for WINDOW_GLOBAL
[task 2022-05-02T07:21:00.259Z] 07:21:00 INFO - STDOUT: 1651476060259 RemoteAgent TRACE Created MessageHandler WINDOW_GLOBAL for session c70761d5-9b88-47bc-b529-fd9cdf5aae3c
[task 2022-05-02T07:21:00.270Z] 07:21:00 INFO - STDOUT: 1651476060269 RemoteAgent TRACE Received command log._applySessionData for destination WINDOW_GLOBAL
[task 2022-05-02T07:21:00.271Z] 07:21:00 INFO - STDOUT: 1651476060270 RemoteAgent TRACE Module windowglobal/log.jsm found for WINDOW_GLOBAL
[task 2022-05-02T07:21:00.272Z] 07:21:00 INFO - STDOUT: 1651476060270 RemoteAgent TRACE Created MessageHandler WINDOW_GLOBAL for session c70761d5-9b88-47bc-b529-fd9cdf5aae3c
[task 2022-05-02T07:21:00.304Z] 07:21:00 INFO - STDOUT: 1651476060307 WebDriver BiDi DEBUG c70761d5-9b88-47bc-b529-fd9cdf5aae3c -> {"id":4,"method":"browsingContext.navigate","params":{"context":"424b3305-aa1a-47ce-8f2c-8f1dde4da9f8","url":"http://web-plat ... r.webdriver%22%2C+navigator.webdriver%29%3B%3C%2Fscript%3E%0A++++++++++++&mime=text%2Fhtml&charset=UTF-8","wait":"complete"}}
[task 2022-05-02T07:21:00.309Z] 07:21:00 INFO - STDOUT: 1651476060307 RemoteAgent TRACE Received command browsingContext.navigate for destination ROOT
[task 2022-05-02T07:21:00.310Z] 07:21:00 INFO - STDOUT: 1651476060308 RemoteAgent TRACE Received command browsingContext._getBaseURL for destination WINDOW_GLOBAL
[task 2022-05-02T07:21:00.311Z] 07:21:00 INFO - STDOUT: 1651476060309 RemoteAgent TRACE Module windowglobal-in-root/browsingContext.jsm not found for WINDOW_GLOBAL
[task 2022-05-02T07:21:00.311Z] 07:21:00 INFO - STDOUT: 1651476060309 RemoteAgent TRACE Received command browsingContext._getBaseURL for destination WINDOW_GLOBAL
[task 2022-05-02T07:21:00.312Z] 07:21:00 INFO - STDOUT: 1651476060312 RemoteAgent TRACE Module windowglobal/browsingContext.jsm found for WINDOW_GLOBAL
[task 2022-05-02T07:21:00.313Z] 07:21:00 INFO - STDOUT: [Child 7488, Main Thread] WARNING: '!CanSend() || !mManager || !mManager->CanSend()', file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:44
[task 2022-05-02T07:21:00.316Z] 07:21:00 INFO - STDOUT: 1651476060315 RemoteAgent TRACE MessageHandler WINDOW_GLOBAL for session c70761d5-9b88-47bc-b529-fd9cdf5aae3c is being destroyed
[task 2022-05-02T07:21:00.317Z] 07:21:00 INFO - STDOUT: 1651476060315 WebDriver BiDi DEBUG c70761d5-9b88-47bc-b529-fd9cdf5aae3c <- {"id":4,"error":"unknown error","message":"AbortError: Actor 'MessageHandlerFrame' destroyed before query 'MessageHandlerFrameParent:sendCommand' was resolved","stacktrace":""}
[task 2022-05-02T07:21:00.318Z] 07:21:00 INFO - STDOUT: 1651476060316 RemoteAgent TRACE Unregistered MessageHandler WINDOW_GLOBAL for session c70761d5-9b88-47bc-b529-fd9cdf5aae3c
[task 2022-05-02T07:21:00.366Z] 07:21:00 INFO - STDOUT: 1651476060377 RemoteAgent DEBUG WebDriverBiDiConnection 4d111f0a-6900-4909-9c5f-07228d47b5d9 closed
[task 2022-05-02T07:21:00.529Z] 07:21:00 INFO - STDOUT: [Parent 2544, BgIOThreadPool #1] WARNING: 'GetLastError() != ERROR_FILE_NOT_FOUND', file /builds/worker/checkouts/gecko/browser/components/shell/nsWindowsShellService.cpp:1391
[task 2022-05-02T07:21:00.530Z] 07:21:00 INFO - STDOUT: FAILED
[task 2022-05-02T07:21:00.531Z] 07:21:00 INFO - STDOUT: [Parent 2544, BgIOThreadPool #1] WARNING: 'GetLastError() != ERROR_FILE_NOT_FOUND', file /builds/worker/checkouts/gecko/browser/components/shell/nsWindowsShellService.cpp:1391
[task 2022-05-02T07:21:01.598Z] 07:21:01 INFO - STDOUT: ================================== FAILURES ===================================
[task 2022-05-02T07:21:01.600Z] 07:21:01 INFO - STDOUT: ______________________ test_navigator_webdriver_enabled _______________________
[task 2022-05-02T07:21:01.601Z] 07:21:01 INFO - STDOUT: inline = <function inline.<locals>.inline at 0x000001E000B86B80>
[task 2022-05-02T07:21:01.602Z] 07:21:01 INFO - STDOUT: browser = <function browser.<locals>._browser at 0x000001E000B86A60>
[task 2022-05-02T07:21:01.602Z] 07:21:01 INFO - STDOUT: async def test_navigator_webdriver_enabled(inline, browser):
[task 2022-05-02T07:21:01.603Z] 07:21:01 INFO - STDOUT: # Request a new browser with only WebDriver BiDi and not Marionette/CDP enabled.
[task 2022-05-02T07:21:01.604Z] 07:21:01 INFO - STDOUT: current_browser = browser(use_bidi=True, extra_prefs={"remote.active-protocols": 1})
[task 2022-05-02T07:21:01.604Z] 07:21:01 INFO - STDOUT: server_port = current_browser.remote_agent_port
[task 2022-05-02T07:21:01.605Z] 07:21:01 INFO - STDOUT:
[task 2022-05-02T07:21:01.605Z] 07:21:01 INFO - STDOUT: async with BidiSession.bidi_only(f"ws://localhost:{server_port}") as bidi_session:
[task 2022-05-02T07:21:01.612Z] 07:21:01 INFO -
[task 2022-05-02T07:21:01.612Z] 07:21:01 INFO - TEST-UNEXPECTED-FAIL | /_mozilla/webdriver/bidi/interface/interface.py | test_navigator_webdriver_enabled - webdriver.bidi.error.UnknownErrorException: unknown error (AbortError: Actor 'MessageHandlerFrame' destroyed before query 'MessageHandlerFrameParent:sendCommand' was resolved)
[task 2022-05-02T07:21:01.612Z] 07:21:01 INFO - inline = <function inline.<locals>.inline at 0x000001E000B86B80>
[task 2022-05-02T07:21:01.612Z] 07:21:01 INFO - browser = <function browser.<locals>._browser at 0x000001E000B86A60>
[task 2022-05-02T07:21:01.612Z] 07:21:01 INFO -
[task 2022-05-02T07:21:01.612Z] 07:21:01 INFO - async def test_navigator_webdriver_enabled(inline, browser):
[task 2022-05-02T07:21:01.612Z] 07:21:01 INFO - # Request a new browser with only WebDriver BiDi and not Marionette/CDP enabled.
[task 2022-05-02T07:21:01.612Z] 07:21:01 INFO - current_browser = browser(use_bidi=True, extra_prefs={"remote.active-protocols": 1})
[task 2022-05-02T07:21:01.612Z] 07:21:01 INFO - server_port = current_browser.remote_agent_port
[task 2022-05-02T07:21:01.612Z] 07:21:01 INFO -
[task 2022-05-02T07:21:01.612Z] 07:21:01 INFO - async with BidiSession.bidi_only(f"ws://localhost:{server_port}") as bidi_session:
[task 2022-05-02T07:21:01.612Z] 07:21:01 INFO - # Until script.evaluate has been implemented use console logging
[task 2022-05-02T07:21:01.612Z] 07:21:01 INFO - # as workaround to retrieve the value for navigator.webdriver.
Description
•