2012793 - Intermittent Android /webdriver/tests/bidi/input/perform_actions/key.py | test_key_down_closes_browsing_context - Failed: DID NOT RAISE <class 'webdriver.bidi.error.NoSuchFrameException'> | single tracking bug

Reporter

Description

•

5 months ago

treeherder

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

[task 2026-01-27T16:02:41.064+00:00] 16:02:41     INFO - 
[task 2026-01-27T16:02:41.064+00:00] 16:02:41     INFO - TEST-PASS | /webdriver/tests/bidi/input/perform_actions/key.py | test_invalid_browsing_context
[task 2026-01-27T16:02:41.064+00:00] 16:02:41     INFO - TEST-UNEXPECTED-FAIL | /webdriver/tests/bidi/input/perform_actions/key.py | test_key_down_closes_browsing_context - Failed: DID NOT RAISE <class 'webdriver.bidi.error.NoSuchFrameException'>
[task 2026-01-27T16:02:41.064+00:00] 16:02:41     INFO - bidi_session = <webdriver.bidi.client.BidiSession object at 0x7fb03ca21e50>
[task 2026-01-27T16:02:41.064+00:00] 16:02:41     INFO - configuration = {'browser': {'args': ['--profile', '/tmp/tmpzgylau1d.mozrunner'], 'binary': None, 'env': {'MINIDUMP_SAVE_PATH': '/buil...CRASHREPORTER_SHUTDOWN': '1', 'MOZ_DISABLE_NONLOCAL_CONNECTIONS': '1', ...}}}, 'host': '127.0.0.1', 'port': 34851, ...}
[task 2026-01-27T16:02:41.064+00:00] 16:02:41     INFO - new_tab = {'children': None, 'clientWindow': 'c85bd1b9-c725-473d-b61a-c14f0372459d', 'context': 'bc927e49-7eb6-4920-865f-b6bfff261fb1', 'originalOpener': None, ...}
[task 2026-01-27T16:02:41.068+00:00] 16:02:41     INFO - inline = <function inline.<locals>.inline at 0x7fb03ca3e3e0>
[task 2026-01-27T16:02:41.069+00:00] 16:02:41     INFO - subscribe_events = <function subscribe_events.<locals>.subscribe_events at 0x7fb03ca3e5c0>
[task 2026-01-27T16:02:41.070+00:00] 16:02:41     INFO - wait_for_event = <function wait_for_event.<locals>.wait_for_event at 0x7fb03ca3e480>
[task 2026-01-27T16:02:41.070+00:00] 16:02:41     INFO - 
[task 2026-01-27T16:02:41.071+00:00] 16:02:41     INFO -     async def test_key_down_closes_browsing_context(
[task 2026-01-27T16:02:41.071+00:00] 16:02:41     INFO -         bidi_session, configuration, new_tab, inline, subscribe_events,
[task 2026-01-27T16:02:41.071+00:00] 16:02:41     INFO -         wait_for_event
[task 2026-01-27T16:02:41.071+00:00] 16:02:41     INFO -     ):
[task 2026-01-27T16:02:41.071+00:00] 16:02:41     INFO -         url = inline("""
[task 2026-01-27T16:02:41.071+00:00] 16:02:41     INFO -             <input onkeydown="window.close()">close</input>
[task 2026-01-27T16:02:41.071+00:00] 16:02:41     INFO -             <script>document.querySelector("input").focus();</script>
[task 2026-01-27T16:02:41.071+00:00] 16:02:41     INFO -             """)
[task 2026-01-27T16:02:41.071+00:00] 16:02:41     INFO -     
[task 2026-01-27T16:02:41.071+00:00] 16:02:41     INFO -         # Opening a new context via `window.open` is required for script to be able
[task 2026-01-27T16:02:41.071+00:00] 16:02:41     INFO -         # to close it.
[task 2026-01-27T16:02:41.071+00:00] 16:02:41     INFO -         await subscribe_events(events=[CONTEXT_LOAD_EVENT])
[task 2026-01-27T16:02:41.071+00:00] 16:02:41     INFO -         on_load = wait_for_event(CONTEXT_LOAD_EVENT)
[task 2026-01-27T16:02:41.071+00:00] 16:02:41     INFO -     
[task 2026-01-27T16:02:41.071+00:00] 16:02:41     INFO -         await bidi_session.script.evaluate(
[task 2026-01-27T16:02:41.071+00:00] 16:02:41     INFO -             expression=f"window.open('{url}')",
[task 2026-01-27T16:02:41.071+00:00] 16:02:41     INFO -             target=ContextTarget(new_tab["context"]),
[task 2026-01-27T16:02:41.071+00:00] 16:02:41     INFO -             await_promise=True
[task 2026-01-27T16:02:41.071+00:00] 16:02:41     INFO -         )
[task 2026-01-27T16:02:41.071+00:00] 16:02:41     INFO -         # Wait for the new context to be created and get it.
[task 2026-01-27T16:02:41.071+00:00] 16:02:41     INFO -         new_context = await on_load
[task 2026-01-27T16:02:41.071+00:00] 16:02:41     INFO -     
[task 2026-01-27T16:02:41.071+00:00] 16:02:41     INFO -         actions = Actions()
[task 2026-01-27T16:02:41.071+00:00] 16:02:41     INFO -         (
[task 2026-01-27T16:02:41.072+00:00] 16:02:41     INFO -             actions.add_key()
[task 2026-01-27T16:02:41.072+00:00] 16:02:41     INFO -             .key_down("w")
[task 2026-01-27T16:02:41.073+00:00] 16:02:41     INFO -             .pause(100 * configuration["timeout_multiplier"])
[task 2026-01-27T16:02:41.073+00:00] 16:02:41     INFO -             .key_up("w")
[task 2026-01-27T16:02:41.073+00:00] 16:02:41     INFO -         )
[task 2026-01-27T16:02:41.074+00:00] 16:02:41     INFO -     
[task 2026-01-27T16:02:41.074+00:00] 16:02:41     INFO - >       with pytest.raises(NoSuchFrameException):
[task 2026-01-27T16:02:41.075+00:00] 16:02:41     INFO - E       Failed: DID NOT RAISE <class 'webdriver.bidi.error.NoSuchFrameException'>
[task 2026-01-27T16:02:41.075+00:00] 16:02:41     INFO - 
[task 2026-01-27T16:02:41.075+00:00] 16:02:41     INFO - actions    = <webdriver.bidi.modules.input.Actions object at 0x7fb03ca23d70>
[task 2026-01-27T16:02:41.075+00:00] 16:02:41     INFO - bidi_session = <webdriver.bidi.client.BidiSession object at 0x7fb03ca21e50>
[task 2026-01-27T16:02:41.076+00:00] 16:02:41     INFO - configuration = {'browser': {'args': ['--profile', '/tmp/tmpzgylau1d.mozrunner'],
[task 2026-01-27T16:02:41.076+00:00] 16:02:41     INFO -              'binary': None,
[task 2026-01-27T16:02:41.077+00:00] 16:02:41     INFO -              'env': {'MINIDUMP_SAVE_PATH': '/builds/worker/workspace/build/blobber_upload_dir',
[task 2026-01-27T16:02:41.077+00:00] 16:02:41     INFO -                      'MOZ_CRASHREPORTER': '1',
[task 2026-01-27T16:02:41.078+00:00] 16:02:41     INFO -                      'MOZ_CRASHREPORTER_SHUTDOWN': '1',
[task 2026-01-27T16:02:41.078+00:00] 16:02:41     INFO -                      'MOZ_DISABLE_NONLOCAL_CONNECTIONS': '1',
[task 2026-01-27T16:02:41.078+00:00] 16:02:41     INFO -                      'RUST_BACKTRACE': '1'}},
[task 2026-01-27T16:02:41.078+00:00] 16:02:41     INFO -  'capabilities': {'moz:firefoxOptions': {'androidDeviceSerial': 'emulator-5554',
[task 2026-01-27T16:02:41.078+00:00] 16:02:41     INFO -                                          'androidPackage': 'org.mozilla.geckoview.test_runner',
[task 2026-01-27T16:02:41.079+00:00] 16:02:41     INFO -                                          'args': ['--profile',
[task 2026-01-27T16:02:41.080+00:00] 16:02:41     INFO -                                                   '/tmp/tmpzgylau1d.mozrunner'],
[task 2026-01-27T16:02:41.081+00:00] 16:02:41     INFO -                                          'env': {'MINIDUMP_SAVE_PATH': '/builds/worker/workspace/build/blobber_upload_dir',
[task 2026-01-27T16:02:41.081+00:00] 16:02:41     INFO -                                                  'MOZ_CRASHREPORTER': '1',
[task 2026-01-27T16:02:41.082+00:00] 16:02:41     INFO -                                                  'MOZ_CRASHREPORTER_SHUTDOWN': '1',
[task 2026-01-27T16:02:41.083+00:00] 16:02:41     INFO -                                                  'MOZ_DISABLE_NONLOCAL_CONNECTIONS': '1',
[task 2026-01-27T16:02:41.083+00:00] 16:02:41     INFO -                                                  'RUST_BACKTRACE': '1'}}},
[task 2026-01-27T16:02:41.084+00:00] 16:02:41     INFO -  'host': '127.0.0.1',
[task 2026-01-27T16:02:41.084+00:00] 16:02:41     INFO -  'port': 34851,
[task 2026-01-27T16:02:41.085+00:00] 16:02:41     INFO -  'target_platform': 'android',
[task 2026-01-27T16:02:41.086+00:00] 16:02:41     INFO -  'timeout_multiplier': 4,
[task 2026-01-27T16:02:41.086+00:00] 16:02:41     INFO -  'webdriver': {'args': ['-vv'], 'binary': '/builds/worker/fetches/geckodriver'}}
[task 2026-01-27T16:02:41.087+00:00] 16:02:41     INFO - inline     = <function inline.<locals>.inline at 0x7fb03ca3e3e0>
[task 2026-01-27T16:02:41.088+00:00] 16:02:41     INFO - new_context = {'context': '2273f732-6231-49fd-8639-2ed189666922',
[task 2026-01-27T16:02:41.088+00:00] 16:02:41     INFO -  'navigation': 'e2d74478-2fd7-4c27-a5f1-2ed68f8e2db0',
[task 2026-01-27T16:02:41.088+00:00] 16:02:41     INFO -  'timestamp': 1769529754587,
[task 2026-01-27T16:02:41.088+00:00] 16:02:41     INFO -  'url': 'https://web-platform.test:8443/webdriver/tests/support/inline.py?doc=%3C%21doctype+html%3E%0A%3Cmeta+charset%3DUTF-8%3E%0A%0A++++++++%3Cinput+onkeydown%3D%22window.close%28%29%22%3Eclose%3C%2Finput%3E%0A++++++++%3Cscript%3Edocument.querySelector%28%22input%22%29.focus%28%29%3B%3C%2Fscript%3E%0A++++++++&mime=text%2Fhtml&charset=UTF-8'}
[task 2026-01-27T16:02:41.088+00:00] 16:02:41     INFO - new_tab    = {'children': None,
[task 2026-01-27T16:02:41.088+00:00] 16:02:41     INFO -  'clientWindow': 'c85bd1b9-c725-473d-b61a-c14f0372459d',
[task 2026-01-27T16:02:41.088+00:00] 16:02:41     INFO -  'context': 'bc927e49-7eb6-4920-865f-b6bfff261fb1',
[task 2026-01-27T16:02:41.088+00:00] 16:02:41     INFO -  'originalOpener': None,
[task 2026-01-27T16:02:41.088+00:00] 16:02:41     INFO -  'parent': None,
[task 2026-01-27T16:02:41.088+00:00] 16:02:41     INFO -  'url': 'about:blank',
[task 2026-01-27T16:02:41.088+00:00] 16:02:41     INFO -  'userContext': 'default'}
[task 2026-01-27T16:02:41.088+00:00] 16:02:41     INFO - on_load    = <Future finished result={'context': '2273f732-623...-2ed189666922', 'navigation': 'e2d74478-2fd...-2ed68f8e2db0', 'timestamp': 1769529754587, 'url': 'https://web-...charset=UTF-8'}>
[task 2026-01-27T16:02:41.088+00:00] 16:02:41     INFO - subscribe_events = <function subscribe_events.<locals>.subscribe_events at 0x7fb03ca3e5c0>
[task 2026-01-27T16:02:41.088+00:00] 16:02:41     INFO - url        = 'https://web-platform.test:8443/webdriver/tests/support/inline.py?doc=%3C%21doctype+html%3E%0A%3Cmeta+charset%3DUTF-8%3E%0A%0A++++++++%3Cinput+onkeydown%3D%22window.close%28%29%22%3Eclose%3C%2Finput%3E%0A++++++++%3Cscript%3Edocument.querySelector%28%22input%22%29.focus%28%29%3B%3C%2Fscript%3E%0A++++++++&mime=text%2Fhtml&charset=UTF-8'
[task 2026-01-27T16:02:41.088+00:00] 16:02:41     INFO - wait_for_event = <function wait_for_event.<locals>.wait_for_event at 0x7fb03ca3e480>
[task 2026-01-27T16:02:41.088+00:00] 16:02:41     INFO - 
[task 2026-01-27T16:02:41.088+00:00] 16:02:41     INFO - tests/web-platform/tests/webdriver/tests/bidi/input/perform_actions/key.py:54: Failed
[task 2026-01-27T16:02:41.088+00:00] 16:02:41     INFO - ..........
[task 2026-01-27T16:02:41.088+00:00] 16:02:41     INFO - TEST-OK | /webdriver/tests/bidi/input/perform_actions/key.py | took 15035ms
[task 2026-01-27T16:02:41.409+00:00] 16:02:41     INFO - STDOUT: =================================== FAILURES ===================================
[task 2026-01-27T16:02:41.409+00:00] 16:02:41     INFO - STDOUT: ____________________ test_key_down_closes_browsing_context _____________________
[task 2026-01-27T16:02:41.409+00:00] 16:02:41     INFO - STDOUT: bidi_session = <webdriver.bidi.client.BidiSession object at 0x7fb03ca21e50>
[task 2026-01-27T16:02:41.410+00:00] 16:02:41     INFO - STDOUT: configuration = {'browser': {'args': ['--profile', '/tmp/tmpzgylau1d.mozrunner'], 'binary': None, 'env': {'MINIDUMP_SAVE_PATH': '/buil...CRASHREPORTER_SHUTDOWN': '1', 'MOZ_DISABLE_NONLOCAL_CONNECTIONS': '1', ...}}}, 'host': '127.0.0.1', 'port': 34851, ...}
[task 2026-01-27T16:02:41.411+00:00] 16:02:41     INFO - STDOUT: new_tab = {'children': None, 'clientWindow': 'c85bd1b9-c725-473d-b61a-c14f0372459d', 'context': 'bc927e49-7eb6-4920-865f-b6bfff261fb1', 'originalOpener': None, ...}
[task 2026-01-27T16:02:41.411+00:00] 16:02:41     INFO - STDOUT: inline = <function inline.<locals>.inline at 0x7fb03ca3e3e0>
[task 2026-01-27T16:02:41.411+00:00] 16:02:41     INFO - STDOUT: subscribe_events = <function subscribe_events.<locals>.subscribe_events at 0x7fb03ca3e5c0>
[task 2026-01-27T16:02:41.412+00:00] 16:02:41     INFO - STDOUT: wait_for_event = <function wait_for_event.<locals>.wait_for_event at 0x7fb03ca3e480>
[task 2026-01-27T16:02:41.412+00:00] 16:02:41     INFO - STDOUT:     async def test_key_down_closes_browsing_context(
[task 2026-01-27T16:02:41.413+00:00] 16:02:41     INFO - STDOUT:         bidi_session, configuration, new_tab, inline, subscribe_events,
[task 2026-01-27T16:02:41.413+00:00] 16:02:41     INFO - STDOUT:         wait_for_event
[task 2026-01-27T16:02:41.414+00:00] 16:02:41     INFO - STDOUT:     ):
[task 2026-01-27T16:02:41.414+00:00] 16:02:41     INFO - STDOUT:         url = inline("""
[task 2026-01-27T16:02:41.414+00:00] 16:02:41     INFO - STDOUT:             <input onkeydown="window.close()">close</input>
[task 2026-01-27T16:02:41.415+00:00] 16:02:41     INFO - STDOUT:             <script>document.querySelector("input").focus();</script>
[task 2026-01-27T16:02:41.415+00:00] 16:02:41     INFO - STDOUT:             """)
[task 2026-01-27T16:02:41.416+00:00] 16:02:41     INFO - STDOUT:     
[task 2026-01-27T16:02:41.416+00:00] 16:02:41     INFO - STDOUT:         # Opening a new context via `window.open` is required for script to be able
[task 2026-01-27T16:02:41.417+00:00] 16:02:41     INFO - STDOUT:         # to close it.
[task 2026-01-27T16:02:41.417+00:00] 16:02:41     INFO - STDOUT:         await subscribe_events(events=[CONTEXT_LOAD_EVENT])
[task 2026-01-27T16:02:41.417+00:00] 16:02:41     INFO - STDOUT:         on_load = wait_for_event(CONTEXT_LOAD_EVENT)
[task 2026-01-27T16:02:41.418+00:00] 16:02:41     INFO - STDOUT:     
[task 2026-01-27T16:02:41.418+00:00] 16:02:41     INFO - STDOUT:         await bidi_session.script.evaluate(
[task 2026-01-27T16:02:41.419+00:00] 16:02:41     INFO - STDOUT:             expression=f"window.open('{url}')",
[task 2026-01-27T16:02:41.419+00:00] 16:02:41     INFO - STDOUT:             target=ContextTarget(new_tab["context"]),
[task 2026-01-27T16:02:41.419+00:00] 16:02:41     INFO - STDOUT:             await_promise=True
[task 2026-01-27T16:02:41.420+00:00] 16:02:41     INFO - STDOUT:         )
[task 2026-01-27T16:02:41.420+00:00] 16:02:41     INFO - STDOUT:         # Wait for the new context to be created and get it.
[task 2026-01-27T16:02:41.421+00:00] 16:02:41     INFO - STDOUT:         new_context = await on_load
[task 2026-01-27T16:02:41.421+00:00] 16:02:41     INFO - STDOUT:     
[task 2026-01-27T16:02:41.421+00:00] 16:02:41     INFO - STDOUT:         actions = Actions()
[task 2026-01-27T16:02:41.422+00:00] 16:02:41     INFO - STDOUT:         (
[task 2026-01-27T16:02:41.422+00:00] 16:02:41     INFO - STDOUT:             actions.add_key()
[task 2026-01-27T16:02:41.423+00:00] 16:02:41     INFO - STDOUT:             .key_down("w")
[task 2026-01-27T16:02:41.423+00:00] 16:02:41     INFO - STDOUT:             .pause(100 * configuration["timeout_multiplier"])
[task 2026-01-27T16:02:41.423+00:00] 16:02:41     INFO - STDOUT:             .key_up("w")
[task 2026-01-27T16:02:41.424+00:00] 16:02:41     INFO - STDOUT:         )
[task 2026-01-27T16:02:41.424+00:00] 16:02:41     INFO - STDOUT:     
[task 2026-01-27T16:02:41.425+00:00] 16:02:41     INFO - STDOUT: >       with pytest.raises(NoSuchFrameException):
[task 2026-01-27T16:02:41.425+00:00] 16:02:41     INFO - STDOUT: E       Failed: DID NOT RAISE <class 'webdriver.bidi.error.NoSuchFrameException'>
[task 2026-01-27T16:02:41.426+00:00] 16:02:41     INFO - STDOUT: actions    = <webdriver.bidi.modules.input.Actions object at 0x7fb03ca23d70>
[task 2026-01-27T16:02:41.426+00:00] 16:02:41     INFO - STDOUT: bidi_session = <webdriver.bidi.client.BidiSession object at 0x7fb03ca21e50>
[task 2026-01-27T16:02:41.428+00:00] 16:02:41     INFO - STDOUT: configuration = {'browser': {'args': ['--profile', '/tmp/tmpzgylau1d.mozrunner'],
[task 2026-01-27T16:02:41.428+00:00] 16:02:41     INFO -              'binary': None,
[task 2026-01-27T16:02:41.428+00:00] 16:02:41     INFO -              'env': {'MINIDUMP_SAVE_PATH': '/builds/worker/workspace/build/blobber_upload_dir',
[task 2026-01-27T16:02:41.428+00:00] 16:02:41     INFO -                      'MOZ_CRASHREPORTER': '1',
[task 2026-01-27T16:02:41.428+00:00] 16:02:41     INFO -                      'MOZ_CRASHREPORTER_SHUTDOWN': '1',
[task 2026-01-27T16:02:41.428+00:00] 16:02:41     INFO -                      'MOZ_DISABLE_NONLOCAL_CONNECTIONS': '1',
[task 2026-01-27T16:02:41.429+00:00] 16:02:41     INFO -                      'RUST_BACKTRACE': '1'}},
[task 2026-01-27T16:02:41.429+00:00] 16:02:41     INFO -  'capabilities': {'moz:firefoxOptions': {'androidDeviceSerial': 'emulator-5554',
[task 2026-01-27T16:02:41.429+00:00] 16:02:41     INFO -                                          'androidPackage': 'org.mozilla.geckoview.test_runner',
[task 2026-01-27T16:02:41.429+00:00] 16:02:41     INFO -                                          'args': ['--profile',
[task 2026-01-27T16:02:41.429+00:00] 16:02:41     INFO -                                                   '/tmp/tmpzgylau1d.mozrunner'],
[task 2026-01-27T16:02:41.429+00:00] 16:02:41     INFO -                                          'env': {'MINIDUMP_SAVE_PATH': '/builds/worker/workspace/build/blobber_upload_dir',
[task 2026-01-27T16:02:41.429+00:00] 16:02:41     INFO -                                                  'MOZ_CRASHREPORTER': '1',
[task 2026-01-27T16:02:41.429+00:00] 16:02:41     INFO -                                                  'MOZ_CRASHREPORTER_SHUTDOWN': '1',
[task 2026-01-27T16:02:41.429+00:00] 16:02:41     INFO -                                                  'MOZ_DISABLE_NONLOCAL_CONNECTIONS': '1',
[task 2026-01-27T16:02:41.429+00:00] 16:02:41     INFO -                                                  'RUST_BACKTRACE': '1'}}},
[task 2026-01-27T16:02:41.429+00:00] 16:02:41     INFO -  'host': '127.0.0.1',
[task 2026-01-27T16:02:41.429+00:00] 16:02:41     INFO -  'port': 34851,
[task 2026-01-27T16:02:41.429+00:00] 16:02:41     INFO -  'target_platform': 'android',
[task 2026-01-27T16:02:41.429+00:00] 16:02:41     INFO -  'timeout_multiplier': 4,
[task 2026-01-27T16:02:41.429+00:00] 16:02:41     INFO -  'webdriver': {'args': ['-vv'], 'binary': '/builds/worker/fetches/geckodriver'}}
[task 2026-01-27T16:02:41.430+00:00] 16:02:41     INFO - STDOUT: inline     = <function inline.<locals>.inline at 0x7fb03ca3e3e0>
[task 2026-01-27T16:02:41.431+00:00] 16:02:41     INFO - STDOUT: new_context = {'context': '2273f732-6231-49fd-8639-2ed189666922',
[task 2026-01-27T16:02:41.431+00:00] 16:02:41     INFO -  'navigation': 'e2d74478-2fd7-4c27-a5f1-2ed68f8e2db0',
[task 2026-01-27T16:02:41.431+00:00] 16:02:41     INFO -  'timestamp': 1769529754587,
[task 2026-01-27T16:02:41.431+00:00] 16:02:41     INFO -  'url': 'https://web-platform.test:8443/webdriver/tests/support/inline.py?doc=%3C%21doctype+html%3E%0A%3Cmeta+charset%3DUTF-8%3E%0A%0A++++++++%3Cinput+onkeydown%3D%22window.close%28%29%22%3Eclose%3C%2Finput%3E%0A++++++++%3Cscript%3Edocument.querySelector%28%22input%22%29.focus%28%29%3B%3C%2Fscript%3E%0A++++++++&mime=text%2Fhtml&charset=UTF-8'}
[task 2026-01-27T16:02:41.432+00:00] 16:02:41     INFO - STDOUT: new_tab    = {'children': None,
[task 2026-01-27T16:02:41.432+00:00] 16:02:41     INFO -  'clientWindow': 'c85bd1b9-c725-473d-b61a-c14f0372459d',
[task 2026-01-27T16:02:41.432+00:00] 16:02:41     INFO -  'context': 'bc927e49-7eb6-4920-865f-b6bfff261fb1',
[task 2026-01-27T16:02:41.432+00:00] 16:02:41     INFO -  'originalOpener': None,
[task 2026-01-27T16:02:41.432+00:00] 16:02:41     INFO -  'parent': None,
[task 2026-01-27T16:02:41.432+00:00] 16:02:41     INFO -  'url': 'about:blank',
[task 2026-01-27T16:02:41.432+00:00] 16:02:41     INFO -  'userContext': 'default'}
[task 2026-01-27T16:02:41.433+00:00] 16:02:41     INFO - STDOUT: on_load    = <Future finished result={'context': '2273f732-623...-2ed189666922', 'navigation': 'e2d74478-2fd...-2ed68f8e2db0', 'timestamp': 1769529754587, 'url': 'https://web-...charset=UTF-8'}>
[task 2026-01-27T16:02:41.433+00:00] 16:02:41     INFO - STDOUT: subscribe_events = <function subscribe_events.<locals>.subscribe_events at 0x7fb03ca3e5c0>
[task 2026-01-27T16:02:41.434+00:00] 16:02:41     INFO - STDOUT: url        = 'https://web-platform.test:8443/webdriver/tests/support/inline.py?doc=%3C%21doctype+html%3E%0A%3Cmeta+charset%3DUTF-8%3E%0A%0A++++++++%3Cinput+onkeydown%3D%22window.close%28%29%22%3Eclose%3C%2Finput%3E%0A++++++++%3Cscript%3Edocument.querySelector%28%22input%22%29.focus%28%29%3B%3C%2Fscript%3E%0A++++++++&mime=text%2Fhtml&charset=UTF-8'
[task 2026-01-27T16:02:41.434+00:00] 16:02:41     INFO - STDOUT: wait_for_event = <function wait_for_event.<locals>.wait_for_event at 0x7fb03ca3e480>
[task 2026-01-27T16:02:41.435+00:00] 16:02:41     INFO - STDOUT: tests/web-platform/tests/webdriver/tests/bidi/input/perform_actions/key.py
[task 2026-01-27T16:02:41.435+00:00] 16:02:41     INFO - STDOUT: :54: Failed
[task 2026-01-27T16:02:41.435+00:00] 16:02:41     INFO - STDOUT: =========================== short test summary info ============================
[task 2026-01-27T16:02:41.436+00:00] 16:02:41     INFO - STDOUT: FAILED tests/web-platform/tests/webdriver/tests/bidi/input/perform_actions/key.py::test_key_down_closes_browsing_context - Failed: DID NOT RAISE <class 'webdriver.bidi.error.NoSuchFrameException'>
[task 2026-01-27T16:02:41.437+00:00] 16:02:41     INFO - STDOUT: ======================== 1 failed, 11 passed in 14.94s =========================
[task 2026-01-27T16:02:41.437+00:00] 16:02:41     INFO - Closing logging queue
[task 2026-01-27T16:02:41.437+00:00] 16:02:41     INFO - queue closed
[task 2026-01-27T16:02:41.479+00:00] 16:02:41     INFO - Starting WebDriver: /builds/worker/fetches/geckodriver --host 127.0.0.1 --port 0 -vv
[task 2026-01-27T16:02:41.589+00:00] 16:02:41     INFO - PID 2513 | 1769529761488	geckodriver	INFO	Listening on 127.0.0.1:37945
[task 2026-01-27T16:02:41.589+00:00] 16:02:41     INFO - PID 2513 | 1769529761488	webdriver::server	TRACE	Build standard route for /status
[task 2026-01-27T16:02:41.590+00:00] 16:02:41     INFO - PID 2513 | 1769529761488	webdriver::server	TRACE	Build standard route for /session
[task 2026-01-27T16:02:41.591+00:00] 16:02:41     INFO - PID 2513 | 1769529761488	webdriver::server	TRACE	Build standard route for /session/{sessionId}
[task 2026-01-27T16:02:41.591+00:00] 16:02:41     INFO - PID 2513 | 1769529761488	webdriver::server	TRACE	Build standard route for /session/{sessionId}/url
[task 2026-01-27T16:02:41.592+00:00] 16:02:41     INFO - PID 2513 | 1769529761488	webdriver::server	TRACE	Build standard route for /session/{sessionId}/url
[task 2026-01-27T16:02:41.592+00:00] 16:02:41     INFO - PID 2513 | 1769529761488	webdriver::server	TRACE	Build standard route for /session/{sessionId}/back
[task 2026-01-27T16:02:41.593+00:00] 16:02:41     INFO - PID 2513 | 1769529761488	webdriver::server	TRACE	Build standard route for /session/{sessionId}/forward
[task 2026-01-27T16:02:41.593+00:00] 16:02:41     INFO - PID 2513 | 1769529761488	webdriver::server	TRACE	Build standard route for /session/{sessionId}/refresh
[task 2026-01-27T16:02:41.594+00:00] 16:02:41     INFO - PID 2513 | 1769529761488	webdriver::server	TRACE	Build standard route for /session/{sessionId}/title
[task 2026-01-27T16:02:41.594+00:00] 16:02:41     INFO - PID 2513 | 1769529761488	webdriver::server	TRACE	Build standard route for /session/{sessionId}/source
[task 2026-01-27T16:02:41.595+00:00] 16:02:41     INFO - PID 2513 | 1769529761488	webdriver::server	TRACE	Build standard route for /session/{sessionId}/window
[task 2026-01-27T16:02:41.595+00:00] 16:02:41     INFO - PID 2513 | 1769529761488	webdriver::server	TRACE	Build standard route for /session/{sessionId}/window/handles
[task 2026-01-27T16:02:41.596+00:00] 16:02:41     INFO - PID 2513 | 1769529761488	webdriver::server	TRACE	Build standard route for /session/{sessionId}/window/new
[task 2026-01-27T16:02:41.596+00:00] 16:02:41     INFO - PID 2513 | 1769529761488	webdriver::server	TRACE	Build standard route for /session/{sessionId}/window
[task 2026-01-27T16:02:41.596+00:00] 16:02:41     INFO - PID 2513 | 1769529761488	webdriver::server	TRACE	Build standard route for /session/{sessionId}/window/size
[task 2026-01-27T16:02:41.597+00:00] 16:02:41     INFO - PID 2513 | 1769529761488	webdriver::server	TRACE	Build standard route for /session/{sessionId}/window/size
[task 2026-01-27T16:02:41.597+00:00] 16:02:41     INFO - PID 2513 | 1769529761488	webdriver::server	TRACE	Build standard route for /session/{sessionId}/window/position
[task 2026-01-27T16:02:41.598+00:00] 16:02:41     INFO - PID 2513 | 1769529761488	webdriver::server	TRACE	Build standard route for /session/{sessionId}/window/position
[task 2026-01-27T16:02:41.598+00:00] 16:02:41     INFO - PID 2513 | 1769529761488	webdriver::server	TRACE	Build standard route for /session/{sessionId}/window/rect
[task 2026-01-27T16:02:41.599+00:00] 16:02:41     INFO - PID 2513 | 1769529761488	webdriver::server	TRACE	Build standard route for /session/{sessionId}/window/rect
[task 2026-01-27T16:02:41.599+00:00] 16:02:41     INFO - PID 2513 | 1769529761488	webdriver::server	TRACE	Build standard route for /session/{sessionId}/window/minimize
[task 2026-01-27T16:02:41.600+00:00] 16:02:41     INFO - PID 2513 | 1769529761488	webdriver::server	TRACE	Build standard route for /session/{sessionId}/window/maximize
[task 2026-01-27T16:02:41.600+00:00] 16:02:41     INFO - PID 2513 | 1769529761488	webdriver::server	TRACE	Build standard route for /session/{sessionId}/window/fullscreen
[task 2026-01-27T16:02:41.601+00:00] 16:02:41     INFO - PID 2513 | 1769529761488	webdriver::server	TRACE	Build standard route for /session/{sessionId}/window
[task 2026-01-27T16:02:41.601+00:00] 16:02:41     INFO - PID 2513 | 1769529761488	webdriver::server	TRACE	Build standard route for /session/{sessionId}/frame
[task 2026-01-27T16:02:41.602+00:00] 16:02:41     INFO - PID 2513 | 1769529761488	webdriver::server	TRACE	Build standard route for /session/{sessionId}/frame/parent
[task 2026-01-27T16:02:41.603+00:00] 16:02:41     INFO - PID 2513 | 1769529761488	webdriver::server	TRACE	Build standard route for /session/{sessionId}/element
[task 2026-01-27T16:02:41.603+00:00] 16:02:41     INFO - PID 2513 | 1769529761488	webdriver::server	TRACE	Build standard route for /session/{sessionId}/element/{elementId}/element
[task 2026-01-27T16:02:41.604+00:00] 16:02:41     INFO - PID 2513 | 1769529761488	webdriver::server	TRACE	Build standard route for /session/{sessionId}/elements
[task 2026-01-27T16:02:41.604+00:00] 16:02:41     INFO - PID 2513 | 1769529761488	webdriver::server	TRACE	Build standard route for /session/{sessionId}/element/{elementId}/elements
[task 2026-01-27T16:02:41.605+00:00] 16:02:41     INFO - PID 2513 | 1769529761488	webdriver::server	TRACE	Build standard route for /session/{sessionId}/shadow/{shadowId}/element
[task 2026-01-27T16:02:41.605+00:00] 16:02:41     INFO - PID 2513 | 1769529761488	webdriver::server	TRACE	Build standard route for /session/{sessionId}/shadow/{shadowId}/elements
[task 2026-01-27T16:02:41.606+00:00] 16:02:41     INFO - PID 2513 | 1769529761488	webdriver::server	TRACE	Build standard route for /session/{sessionId}/element/active
[task 2026-01-27T16:02:41.606+00:00] 16:02:41     INFO - PID 2513 | 1769529761488	webdriver::server	TRACE	Build standard route for /session/{sessionId}/element/{elementId}/shadow
[task 2026-01-27T16:02:41.607+00:00] 16:02:41     INFO - PID 2513 | 1769529761488	webdriver::server	TRACE	Build standard route for /session/{sessionId}/element/{elementId}/displayed
[task 2026-01-27T16:02:41.608+00:00] 16:02:41     INFO - PID 2513 | 1769529761488	webdriver::server	TRACE	Build standard route for /session/{sessionId}/element/{elementId}/selected
[task 2026-01-27T16:02:41.608+00:00] 16:02:41     INFO - PID 2513 | 1769529761488	webdriver::server	TRACE	Build standard route for /session/{sessionId}/element/{elementId}/attribute/{name}
[task 2026-01-27T16:02:41.608+00:00] 16:02:41     INFO - PID 2513 | 1769529761488	webdriver::server	TRACE	Build standard route for /session/{sessionId}/element/{elementId}/property/{name}
[task 2026-01-27T16:02:41.609+00:00] 16:02:41     INFO - PID 2513 | 1769529761488	webdriver::server	TRACE	Build standard route for /session/{sessionId}/element/{elementId}/css/{propertyName}
[task 2026-01-27T16:02:41.609+00:00] 16:02:41     INFO - PID 2513 | 1769529761488	webdriver::server	TRACE	Build standard route for /session/{sessionId}/element/{elementId}/text
[task 2026-01-27T16:02:41.610+00:00] 16:02:41     INFO - PID 2513 | 1769529761488	webdriver::server	TRACE	Build standard route for /session/{sessionId}/element/{elementId}/computedlabel
[task 2026-01-27T16:02:41.610+00:00] 16:02:41     INFO - PID 2513 | 1769529761488	webdriver::server	TRACE	Build standard route for /session/{sessionId}/element/{elementId}/computedrole
[task 2026-01-27T16:02:41.611+00:00] 16:02:41     INFO - PID 2513 | 1769529761488	webdriver::server	TRACE	Build standard route for /session/{sessionId}/element/{elementId}/name
[task 2026-01-27T16:02:41.611+00:00] 16:02:41     INFO - PID 2513 | 1769529761488	webdriver::server	TRACE	Build standard route for /session/{sessionId}/element/{elementId}/rect
[task 2026-01-27T16:02:41.612+00:00] 16:02:41     INFO - PID 2513 | 1769529761488	webdriver::server	TRACE	Build standard route for /session/{sessionId}/element/{elementId}/enabled
[task 2026-01-27T16:02:41.612+00:00] 16:02:41     INFO - PID 2513 | 1769529761488	webdriver::server	TRACE	Build standard route for /session/{sessionId}/execute/sync
[task 2026-01-27T16:02:41.613+00:00] 16:02:41     INFO - PID 2513 | 1769529761488	webdriver::server	TRACE	Build standard route for /session/{sessionId}/execute/async
[task 2026-01-27T16:02:41.613+00:00] 16:02:41     INFO - PID 2513 | 1769529761488	webdriver::server	TRACE	Build standard route for /session/{sessionId}/cookie
[task 2026-01-27T16:02:41.614+00:00] 16:02:41     INFO - PID 2513 | 1769529761488	webdriver::server	TRACE	Build standard route for /session/{sessionId}/cookie/{name}
[task 2026-01-27T16:02:41.614+00:00] 16:02:41     INFO - PID 2513 | 1769529761488	webdriver::server	TRACE	Build standard route for /session/{sessionId}/cookie
[task 2026-01-27T16:02:41.615+00:00] 16:02:41     INFO - PID 2513 | 1769529761488	webdriver::server	TRACE	Build standard route for /session/{sessionId}/cookie
[task 2026-01-27T16:02:41.615+00:00] 16:02:41     INFO - PID 2513 | 1769529761488	webdriver::server	TRACE	Build standard route for /session/{sessionId}/cookie/{name}
[task 2026-01-27T16:02:41.616+00:00] 16:02:41     INFO - PID 2513 | 1769529761488	webdriver::server	TRACE	Build standard route for /session/{sessionId}/timeouts
[task 2026-01-27T16:02:41.616+00:00] 16:02:41     INFO - PID 2513 | 1769529761488	webdriver::server	TRACE	Build standard route for /session/{sessionId}/timeouts
[task 2026-01-27T16:02:41.617+00:00] 16:02:41     INFO - PID 2513 | 1769529761488	webdriver::server	TRACE	Build standard route for /session/{sessionId}/element/{elementId}/click
[task 2026-01-27T16:02:41.617+00:00] 16:02:41     INFO - PID 2513 | 1769529761488	webdriver::server	TRACE	Build standard route for /session/{sessionId}/element/{elementId}/clear
[task 2026-01-27T16:02:41.618+00:00] 16:02:41     INFO - PID 2513 | 1769529761488	webdriver::server	TRACE	Build standard route for /session/{sessionId}/element/{elementId}/value
[task 2026-01-27T16:02:41.618+00:00] 16:02:41     INFO - PID 2513 | 1769529761488	webdriver::server	TRACE	Build standard route for /session/{sessionId}/alert/dismiss
[task 2026-01-27T16:02:41.619+00:00] 16:02:41     INFO - PID 2513 | 1769529761488	webdriver::server	TRACE	Build standard route for /session/{sessionId}/alert/accept
[task 2026-01-27T16:02:41.619+00:00] 16:02:41     INFO - PID 2513 | 1769529761488	webdriver::server	TRACE	Build standard route for /session/{sessionId}/alert/text
[task 2026-01-27T16:02:41.620+00:00] 16:02:41     INFO - PID 2513 | 1769529761488	webdriver::server	TRACE	Build standard route for /session/{sessionId}/alert/text
[task 2026-01-27T16:02:41.620+00:00] 16:02:41     INFO - PID 2513 | 1769529761488	webdriver::server	TRACE	Build standard route for /session/{sessionId}/screenshot
[task 2026-01-27T16:02:41.621+00:00] 16:02:41     INFO - PID 2513 | 1769529761488	webdriver::server	TRACE	Build standard route for /session/{sessionId}/element/{elementId}/screenshot
[task 2026-01-27T16:02:41.622+00:00] 16:02:41     INFO - PID 2513 | 1769529761488	webdriver::server	TRACE	Build standard route for /session/{sessionId}/actions
[task 2026-01-27T16:02:41.622+00:00] 16:02:41     INFO - PID 2513 | 1769529761488	webdriver::server	TRACE	Build standard route for /session/{sessionId}/actions
[task 2026-01-27T16:02:41.623+00:00] 16:02:41     INFO - PID 2513 | 1769529761488	webdriver::server	TRACE	Build standard route for /session/{sessionId}/permissions
[task 2026-01-27T16:02:41.623+00:00] 16:02:41     INFO - PID 2513 | 1769529761488	webdriver::server	TRACE	Build standard route for /session/{sessionId}/print
[task 2026-01-27T16:02:41.624+00:00] 16:02:41     INFO - PID 2513 | 1769529761488	webdriver::server	TRACE	Build standard route for /session/{sessionId}/privacy
[task 2026-01-27T16:02:41.624+00:00] 16:02:41     INFO - PID 2513 | 1769529761488	webdriver::server	TRACE	Build standard route for /session/{sessionId}/privacy
[task 2026-01-27T16:02:41.625+00:00] 16:02:41     INFO - PID 2513 | 1769529761488	webdriver::server	TRACE	Build standard route for /session/{sessionId}/webauthn/authenticator
[task 2026-01-27T16:02:41.625+00:00] 16:02:41     INFO - PID 2513 | 1769529761488	webdriver::server	TRACE	Build standard route for /session/{sessionId}/webauthn/authenticator/{authenticatorId}
[task 2026-01-27T16:02:41.626+00:00] 16:02:41     INFO - PID 2513 | 1769529761488	webdriver::server	TRACE	Build standard route for /session/{sessionId}/webauthn/authenticator/{authenticatorId}/credential
[task 2026-01-27T16:02:41.626+00:00] 16:02:41     INFO - PID 2513 | 1769529761488	webdriver::server	TRACE	Build standard route for /session/{sessionId}/webauthn/authenticator/{authenticatorId}/credentials
[task 2026-01-27T16:02:41.627+00:00] 16:02:41     INFO - PID 2513 | 1769529761488	webdriver::server	TRACE	Build standard route for /session/{sessionId}/webauthn/authenticator/{authenticatorId}/credentials/{credentialId}
[task 2026-01-27T16:02:41.627+00:00] 16:02:41     INFO - PID 2513 | 1769529761488	webdriver::server	TRACE	Build standard route for /session/{sessionId}/webauthn/authenticator/{authenticatorId}/credentials
[task 2026-01-27T16:02:41.628+00:00] 16:02:41     INFO - PID 2513 | 1769529761488	webdriver::server	TRACE	Build standard route for /session/{sessionId}/webauthn/authenticator/{authenticatorId}/uv
[task 2026-01-27T16:02:41.628+00:00] 16:02:41     INFO - PID 2513 | 1769529761488	webdriver::server	TRACE	Build vendor route for /session/{sessionId}/moz/context
[task 2026-01-27T16:02:41.629+00:00] 16:02:41     INFO - PID 2513 | 1769529761488	webdriver::server	TRACE	Build vendor route for /session/{sessionId}/moz/context
[task 2026-01-27T16:02:41.629+00:00] 16:02:41     INFO - PID 2513 | 1769529761488	webdriver::server	TRACE	Build vendor route for /session/{sessionId}/moz/addon/install
[task 2026-01-27T16:02:41.630+00:00] 16:02:41     INFO - PID 2513 | 1769529761488	webdriver::server	TRACE	Build vendor route for /session/{sessionId}/moz/addon/uninstall
[task 2026-01-27T16:02:41.631+00:00] 16:02:41     INFO - PID 2513 | 1769529761488	webdriver::server	TRACE	Build vendor route for /session/{sessionId}/moz/screenshot/full
[task 2026-01-27T16:02:41.631+00:00] 16:02:41     INFO - Webdriver started successfully.
[task 2026-01-27T16:02:41.631+00:00] 16:02:41     INFO - Starting runner
[task 2026-01-27T16:02:41.893+00:00] 16:02:41     INFO - TEST-START | /webdriver/tests/bidi/input/perform_actions/key_events.py

amarc

Comment 1

•

5 months ago

hi :jmoss, could you please take a look at this? Backfills are not leading to a specific push, seems worker related

Flags: needinfo?(jmoss)

:jmoss

Comment 2

•

5 months ago

Adding :aerickson as it's android.

Flags: needinfo?(jmoss) → needinfo?(aerickson)

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

Comment 3

•

5 months ago

Note that on autoland we do not run all the tests everytime and in different orders / chunks. So the constellation we have here could be unique and as such a backfill will not help because then the same selection of tests is run.

Nevertheless it would be good to know if something has changed for the Android devices or emulators.

Julian Descottes [:jdescottes]

Comment 4

•

5 months ago

(In reply to Henrik Skupin [:whimboo][⌚️UTC+1] from comment #3)

Note that on autoland we do not run all the tests everytime and in different orders / chunks. So the constellation we have here could be unique and as such a backfill will not help because then the same selection of tests is run.

Nevertheless it would be good to know if something has changed for the Android devices or emulators.

Backfills triggered from autoland jobs preserve the test groups, so they should still be valuable.

Andrew Erickson [:aerickson]

Comment 5

•

5 months ago

This looks like an android test running in a docker container on an emulator.

We've only seen this failure once (failure to raise an exception)?

We did tweak the hostutils version recently, but the linux change has been landed for awhile (3 months, https://bugzilla.mozilla.org/show_bug.cgi?id=1993177). I don't thing anything major has changed in the Linux VMs, but not sure about the docker container this runs in.

Flags: needinfo?(aerickson)

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

Comment 6

•

5 months ago

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

Backfills triggered from autoland jobs preserve the test groups, so they should still be valuable.

Yes, what I meant is that the root cause of this failure may go back much further.

Here an excerpt from the Android emulator log:

01-27 18:14:55.261  6668  6734 I Gecko   : 1769537695261	RemoteAgent	TRACE	Received command input.performActions for destination ROOT
01-27 18:14:55.272  6668  6734 I Gecko   : 1769537695272	RemoteAgent	TRACE	Dispatching tick 1/3
01-27 18:14:55.273  6668  6734 I Gecko   : 1769537695273	RemoteAgent	TRACE	 Dispatch KeyDownAction with key-0 w
01-27 18:14:55.276  6974  7025 I Gecko   : 1769537695276	RemoteAgent	TRACE	Received command input._dispatchEvent for destination WINDOW_GLOBAL
01-27 18:14:55.320  6668  6734 I Gecko   : 1769537695320	RemoteAgent	TRACE	Dispatching tick 2/3
01-27 18:14:55.320  6668  6734 I Gecko   : 1769537695320	RemoteAgent	TRACE	 Dispatch PauseAction with key-0 400
01-27 18:14:55.742  6668  6734 I Gecko   : 1769537695742	RemoteAgent	TRACE	Dispatching tick 3/3
01-27 18:14:55.742  6668  6734 I Gecko   : 1769537695742	RemoteAgent	TRACE	 Dispatch KeyUpAction with key-0 w
01-27 18:14:55.744  6974  7025 I Gecko   : 1769537695744	RemoteAgent	TRACE	Received command input._dispatchEvent for destination WINDOW_GLOBAL
01-27 18:14:55.747  6974  7025 I Gecko   : 1769537695747	RemoteAgent	TRACE	Received command input._finalizeAction for destination WINDOW_GLOBAL
01-27 18:14:55.815   379   413 I netd    : tetherGetStats() -> {[]} <0.68ms>
01-27 18:14:55.822   379   413 I netd    : bandwidthSetGlobalAlert(2097152) <0.26ms>
01-27 18:14:55.825   379   413 I netd    : bandwidthRemoveInterfaceQuota(eth0) <0.60ms>
01-27 18:14:55.826  6668  6734 I Gecko   : 1769537695826	RemoteAgent	TRACE	ParentWebProgressListener Stop watching updates for browsing context [context=6442450945]
01-27 18:14:55.826  6668  6734 I Gecko   : 1769537695826	RemoteAgent	TRACE	ParentWebProgressListener All browsing contexts for this web progress deleted, removing the progress listener [context=6442450945]
01-27 18:14:55.826  6668  6734 I Gecko   : 1769537695826	RemoteAgent	TRACE	ParentWebProgressListener Removing the web progress from monitored web progress [context=6442450945]
01-27 18:14:55.827   379   413 I netd    : bandwidthSetInterfaceQuota(eth0, 9223372036854775807) <0.86ms>
01-27 18:14:55.828  6668  6734 I Gecko   : 1769537695828	RemoteAgent	TRACE	[f3779347-6c73-431e-aee0-b6b2e6f6b556] Navigation already marked as finished, navigationId: 0efd5424-7ed2-4b60-9f8d-8bb24d68e85b
01-27 18:14:55.829  6974  7025 E Isolated Web Content: [JavaScript Error: "uncaught exception: undefined"]
01-27 18:14:55.830  6974  7025 I Gecko   : 1769537695830	RemoteAgent	TRACE	Received DOM event pagehide for [object HTMLDocument]
01-27 18:14:55.831  6840  6893 D EGL_emulation: app_time_stats: avg=396.52ms min=82.75ms max=999.89ms count=4
01-27 18:14:55.834  6974  7025 I Gecko   : 1769537695834	RemoteAgent	TRACE	MessageHandler WINDOW_GLOBAL for session bc288baa-8250-4994-a328-9d55525d4e21 is being destroyed
01-27 18:14:55.840  6668  6734 I Gecko   : 1769537695840	RemoteAgent	DEBUG	WebDriverBiDiConnection b4a66a54-ff26-4350-a097-8163d5520b29 <- {"type":"success","id":9,"result":{}}
01-27 18:14:55.842  6668  6734 W GeckoViewAutofill: Disregarding old session f156f372-230a-413a-887a-7e419032ab00
01-27 18:14:55.846  6668  6734 E GeckoConsole: [JavaScript Error: "TypeError: can't access property "WindowEventDispatcher", win is null" {file: "resource://gre/modules/GeckoViewSessionStore.sys.mjs" line: 149}]
01-27 18:14:55.846  6668  6734 E GeckoConsole: onTabStateUpdate@resource://gre/modules/GeckoViewSessionStore.sys.mjs:149:5
01-27 18:14:55.846  6668  6734 E GeckoConsole: updateSessionStoreFromTabListener@resource://gre/modules/GeckoViewSessionStore.sys.mjs:243:10
01-27 18:14:55.846  6668  6734 E GeckoConsole: SSF_updateSessionStore@resource://gre/modules/SessionStoreFunctions.sys.mjs:46:27
01-27 18:14:55.846  6668  6734 E GeckoConsole: UpdateSessionStore@resource://gre/modules/SessionStoreFunctions.sys.mjs:16:46
01-27 18:14:55.850  6974  7025 I Gecko   : 1769537695850	RemoteAgent	TRACE	Unregistered MessageHandler WINDOW_GLOBAL for session bc288baa-8250-4994-a328-9d55525d4e21
01-27 18:14:55.852  6974  6974 I ServiceChildProcess: Destroying GeckoServiceChildProcess
01-27 18:14:55.854  6668  6734 E GeckoConsole: [JavaScript Error: "TypeError: can't access property "sendRequest", this.eventDispatcher is undefined" {file: "resource:///actors/ContentDelegateParent.sys.mjs" line: 61}]
01-27 18:14:55.854  6974  6974 I st_runner:tab33: System.exit called, status: 0
01-27 18:14:55.854  6974  6974 I AndroidRuntime: VM exiting with result code 0, cleanup skipped.
01-27 18:14:55.870   575  1370 I ActivityManager: Process org.mozilla.geckoview.test_runner:tab33 (pid 6974) has died: fg  SVC

It shows that we actually send the keydown event and that the window gets closed. But that closing happens with a longer delay as expected.

Note that so far this failure happened only once (beside the backfills) so I do not think that we have to account it for high frequency. So i still think that there is something in the order of tests which causes this delayed closing of the window.

I don't think that we have to focus on this failure at the moment.

Summary: High frequency Android 14 Lite /webdriver/tests/bidi/input/perform_actions/key.py | test_key_down_closes_browsing_context - Failed: DID NOT RAISE <class 'webdriver.bidi.error.NoSuchFrameException'> | single tracking bug → Intermittent Android /webdriver/tests/bidi/input/perform_actions/key.py | test_key_down_closes_browsing_context - Failed: DID NOT RAISE <class 'webdriver.bidi.error.NoSuchFrameException'> | single tracking bug

Comment hidden (Intermittent Failures Robot)

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

Updated

•

5 months ago

Duplicate of this bug: 2013804

Cristina Horotan [:chorotan]

Comment 9

•

5 months ago

Started to fail again here

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

Comment 10

•

5 months ago

This failure is not only Android related. Bug 2013804 shows it for desktop as well.(In reply to Cristina Horotan [:chorotan] from comment #9)

Started to fail again here

This link is wrong. There is no failing test for that revision.

But let me check back tomorrow if there is actually a pattern that we can see here.

Flags: needinfo?(chorotan)

Cristina Horotan [:chorotan]

Comment 11

•

5 months ago

•

Edited

Please check this link and this link

Flags: needinfo?(chorotan)

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

Comment 12

•

5 months ago

Ok, thank you. Note that there is no need to run backfills for this particular failure as we know that those would fail anyway.

Comment hidden (Intermittent Failures Robot)

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

Comment 14

•

5 months ago

I see different things here:

So far still no failure on mozilla-central
As it looks like it varies a lot in which test chunk this test is actually run. On autoland we only run some tests and in most cases this failing test is not part of the selected tests at all, and for all jobs it's run as part of Wd6 or Wd5 and passes just fine.
When it is run we only run the invalid.py test for performActions as well - nothing else runs before
Within the key.py file we only run test_invalid_browsing_context before (whether if the test is passing or failing)
The first failure was reported on February 2nd but backfills show this problem exists already for a longer time (at least January 26th)

Overall I think that this is a race condition and maybe has been made more visible as part of the landing of my patch from bug 1934326:
https://github.com/mozilla-firefox/firefox/commit/e21815e6380e

Here we reduced the pause from 250ms to 100ms before trying to dispatch the expect to fail final action. I would suggest that we increase the pause duration so that the browser under test has enough time to actually close the tab.

Comment 15

•

5 months ago

I'll continue to run some more backfills given that it is still strange that it started out of a sudden. Also I will try pushing some jobs to try to hopefully being able to nail down the order of tests / commands to run to replicate the delay in closing the tab.

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

Comment 16

•

5 months ago

So I actually stripped the tests under input/performActions/ to only contain key.py and the single failing test. Pushing just this to try with the path to the folder I was able to see it failing and that permanently:

https://treeherder.mozilla.org/jobs?repo=try&revision=ac051c02ecfde248ab618950cd40bbc5347479d3&selectedTaskRun=SD1PVvkkSLG8x5yMCabT2A.0

Still I have no idea how to reproduce it locally with opt nor with debug builds. It's not failing at all. So something special must be set when run in CI on autoland and try. Suspicious as well that when running all the tests we do not see the failure.

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

Comment 17

•

5 months ago

In case when it's working the following output can be seen in the emulator log:

01-26 07:22:17.165 18790 18813 I Gecko   : 1769412137165	RemoteAgent	TRACE	Dispatching tick 1/3
01-26 07:22:17.165 18790 18813 I Gecko   : 1769412137165	RemoteAgent	TRACE	 Dispatch KeyDownAction with key-0 w
01-26 07:22:17.171 18790 18813 D GeckoViewContentDelegateParent: receiveMessage: GeckoView:FirstContentfulPaint
01-26 07:22:17.172 18790 18813 D GeckoViewContentDelegateParent: receiveMessage: GeckoView:DOMMetaViewportFit
01-26 07:22:17.176 19006 19043 I Gecko   : 1769412137176	RemoteAgent	TRACE	Received command input._dispatchEvent for destination WINDOW_GLOBAL
01-26 07:22:17.224 18790 18813 D GeckoViewContent: handleEvent: DOMWindowClose
01-26 07:22:17.226 18790 18813 D GeckoViewModule: dispatch GeckoView:WebExtension:SetTabActive, data={"active":false}
01-26 07:22:17.226 18790 18813 D GeckoViewTab: onEvent: event=GeckoView:WebExtension:SetTabActive, data={"active":false}
01-26 07:22:17.230 18790 18813 I Gecko   : 1769412137229	RemoteAgent	TRACE	Dispatching tick 2/3
01-26 07:22:17.230 18790 18813 I Gecko   : 1769412137230	RemoteAgent	TRACE	 Dispatch PauseAction with key-0 400
01-26 07:22:17.267 18790 18813 D GeckoViewContent: handleEvent: DOMWindowClose
01-26 07:22:17.268 18790 18813 D GeckoViewModule: dispatch GeckoView:WebExtension:SetTabActive, data={"active":true}
01-26 07:22:17.268 18790 18813 D GeckoViewTab: onEvent: event=GeckoView:WebExtension:SetTabActive, data={"active":true}
01-26 07:22:17.269 18790 18813 I Gecko   : nsWindow[0x75caa36d1c00]::Show 0
01-26 07:22:17.269 18790 18813 I Gecko   : nsWindow[0x75caa43ca700]::Show 1
01-26 07:22:17.271 19006 19043 D GeckoViewSelectionActionDelegate[C]: handleEvent: visibilitychange
01-26 07:22:17.272 19006 19043 D GeckoViewAutoFill[C]: handleEvent: focusout
01-26 07:22:17.272 18790 18813 D GeckoViewNavigation: onDisable
01-26 07:22:17.272 19006 19043 D GeckoViewAutoFill[C]: Auto-fill focus on null
01-26 07:22:17.273 18790 18813 D GeckoViewProcessHangMonitor: onDisable
01-26 07:22:17.273 18790 18813 D GeckoViewModule: unregisterListener
01-26 07:22:17.273 18790 18813 D GeckoViewProcessHangMonitor: onDestroy
01-26 07:22:17.277 18790 18813 I Gecko   : 1769412137277	RemoteAgent	TRACE	ParentWebProgressListener Stop watching updates for browsing context [context=6442450945]
01-26 07:22:17.277 18790 18813 I Gecko   : 1769412137277	RemoteAgent	TRACE	ParentWebProgressListener All browsing contexts for this web progress deleted, removing the progress listener [context=6442450945]
01-26 07:22:17.277 18790 18813 I Gecko   : 1769412137277	RemoteAgent	TRACE	ParentWebProgressListener Removing the web progress from monitored web progress [context=6442450945]
01-26 07:22:17.278 18790 18813 I Gecko   : 1769412137278	RemoteAgent	TRACE	[c505a010-c4b6-48e5-9601-d2b1b8ba9c70] Navigation already marked as finished, navigationId: be49c79c-0e74-45a2-908a-b68a651b0f87
01-26 07:22:17.278 18790 18813 D GeckoViewSessionStore: observe browsing-context-discarded
01-26 07:22:17.279 19006 19043 D GeckoViewSelectionActionDelegate[C]: handleEvent: visibilitychange
01-26 07:22:17.279 19006 19043 D GeckoViewAutoFill[C]: handleEvent: pagehide
01-26 07:22:17.280 18790 18813 D GeckoViewSessionStore: observe browsing-context-discarded

Here we see the DOMWindowClose event and browsing-context-discarded observer notification after 100ms indicating that the window/document is gone.

But in a failing case I see:

02-03 15:02:08.627  5618  5686 I Gecko   : 1770130928627	RemoteAgent	TRACE	Dispatching tick 1/3
02-03 15:02:08.627  5618  5686 I Gecko   : 1770130928627	RemoteAgent	TRACE	 Dispatch KeyDownAction with key-0 w
02-03 15:02:08.635  6016  6056 I Gecko   : 1770130928635	RemoteAgent	TRACE	Received command input._dispatchEvent for destination WINDOW_GLOBAL
02-03 15:02:08.640  5618  5686 I Gecko   : 1770130928640	RemoteAgent	TRACE	ParentWebProgressListener Loading state: flags: 786448, status: 0,  isStart: false, isStop: true, isNetwork: true, isBindingAborted: false, targetURI: https://web-platform.test:8443/webdriver/tests/support/inline.py?doc=%3C%21doctype+html%3E%0A%3Cmeta+charset%3DUTF-8%3E%0A%0A ... ++%3Cscript%3Edocument.querySelector%28%22input%22%29.focus%28%29%3B%3C%2Fscript%3E%0A++++++++&mime=text%2Fhtml&charset=UTF-8 [context=6442450945]
02-03 15:02:08.640  5618  5686 I Gecko   : 1770130928640	RemoteAgent	TRACE	[30a59c71-1764-4b6e-8abd-a5619067a1b1] Navigation finished for url: https://web-platform.test:8443/webdriver/tests/support/inline.py?doc=%3C%21doctype+html%3E%0A%3Cmeta+charset%3DUTF-8%3E%0A%0A ... ++%3Cscript%3Edocument.querySelector%28%22input%22%29.focus%28%29%3B%3C%2Fscript%3E%0A++++++++&mime=text%2Fhtml&charset=UTF-8 (730de9d5-850b-4eaf-ba6f-4bae1e9240fe)
02-03 15:02:08.641  5618  5686 D GeckoViewContentDelegateParent: receiveMessage: GeckoView:FirstContentfulPaint
02-03 15:02:08.642  5618  5686 D GeckoViewContentDelegateParent: receiveMessage: GeckoView:DOMMetaViewportFit
02-03 15:02:08.725  5618  5686 D GeckoViewContent: handleEvent: DOMWindowClose
02-03 15:02:08.726  5618  5686 D GeckoViewModule: dispatch GeckoView:WebExtension:SetTabActive, data={"active":false}
02-03 15:02:08.726  5618  5686 D GeckoViewTab: onEvent: event=GeckoView:WebExtension:SetTabActive, data={"active":false}
02-03 15:02:08.733  5618  5686 I Gecko   : 1770130928733	RemoteAgent	TRACE	Dispatching tick 2/3
02-03 15:02:08.733  5618  5686 I Gecko   : 1770130928733	RemoteAgent	TRACE	 Dispatch PauseAction with key-0 400
02-03 15:02:09.054  2541  2572 W ogle.android.gm: Suspending all threads took: 5.453ms
02-03 15:02:09.112  6016  6056 D GeckoViewAutoFill[C]: Auto-fill focus on INPUT
02-03 15:02:09.114  6016  6056 E Isolated Web Content: [JavaScript Error: "uncaught exception: undefined"]
02-03 15:02:09.175  5618  5686 I Gecko   : 1770130929175	RemoteAgent	TRACE	Dispatching tick 3/3
02-03 15:02:09.176  5618  5686 I Gecko   : 1770130929176	RemoteAgent	TRACE	 Dispatch KeyUpAction with key-0 w
02-03 15:02:09.178  6016  6056 I Gecko   : 1770130929178	RemoteAgent	TRACE	Received command input._dispatchEvent for destination WINDOW_GLOBAL
02-03 15:02:09.189   565   581 D CompatibilityChangeReporter: Compat change id reported: 135634846; UID 10192; state: DISABLED
02-03 15:02:09.190   565   597 D CompatibilityChangeReporter: Compat change id reported: 143937733; UID 10192; state: ENABLED
02-03 15:02:09.194  5618  5727 D ServiceAllocator: org.mozilla.gecko.process.GeckoChildProcessServices$tab18 updateBindings: FOREGROUND priority, 0 importance, not connected pid, 3 successful binds, 0 failed binds, 0 successful unbinds
[..]
02-03 15:02:09.362  5618  5686 D GeckoViewSessionStore: observe browsing-context-discarded

Only a DOMWindowClose can be seen immediately and the browsing-context-discarded observer notification is very much delayed by ~600ms, which is 6 times larger than usual.

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

Comment 18

•

5 months ago

I picked an older revision from autoland and triggered all the Wdspec tests for debug. Surprisingly none of these test jobs actually run the bidi/input/performActions tests and as such are green.

https://treeherder.mozilla.org/jobs?repo=autoland&searchStr=wd%2Candroid%2Cdebug&revision=ff13281180083d18ef9c71e44e93c977c62ca3a6

Is there something wrong with scheduling? Do we have a different chunking mechanism for those jobs that are triggered regularly each ~20 commits with all chunks compared to the normally randomly picked ones? It looks like we miss to run a lot of tests for these random jobs.

Andrew, do you have an idea? Most likely we should handle that in a different bug when you as well see this problematic.

Flags: needinfo?(ahal)

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

Comment 19

•

5 months ago

After discussing with Aryx the issue with not running the test comes from the fact that the Gecko decision task does not include the specific path in the file manifests-by-task.json.gz which is used to control which tests are run. I think that we can ignore this particular topic for this bug now.

The real question is still why does it sometimes take that long for tab to be closed. Olivia, do you have some tipps in how to better analyze that? Are there additional logs that we could enable to retrieve further information? Who else from the GeckoView folks could help us here? Thanks.

Flags: needinfo?(ahal) → needinfo?(ohall)

Iulian Moraru

Comment 20

•

5 months ago

This happened again: https://treeherder.mozilla.org/jobs?repo=autoland&selectedTaskRun=PlRoRsLrTVyWRqVrXSI_xA.0&resultStatus=testfailed%2Cbusted%2Cexception%2Crunnable&revision=d5f37c5da1a9148f9abc34272e816779d6a77e09

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

Comment 21

•

5 months ago

Thanks, but we don’t need additional comments when this failure occurs.

The tests to run are selected by the Bugbug service, and the Gecko decision task then produces the corresponding manifests-by-task.json.gz. Since the test is failing more frequently now, it is also being selected to run more often, which naturally leads to a higher observed ratio.

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

Comment 22

•

5 months ago

The pointer mouse variant is currently marked as [PASS, FAIL] when async mouse events are not sent. Based on that, I assume the same issue could apply to the key variant as well, and we may need to mark that test in the same way until we understand why closing the tab takes so long.

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

Comment 23

•

5 months ago

Attached file Bug 2012793 - [wdspec] Temporarily mark "test_key_down_closes_browsing_context" as intermittently failing on Android. — Details

Phabricator Automation

Updated

•

5 months ago

Assignee: nobody → hskupin

Status: NEW → ASSIGNED

Olivia Hall [:olivia]

Comment 24

•

5 months ago

(In reply to Henrik Skupin [:whimboo][⌚️UTC+1] from comment #19)

After discussing with Aryx the issue with not running the test comes from the fact that the Gecko decision task does not include the specific path in the file manifests-by-task.json.gz which is used to control which tests are run. I think that we can ignore this particular topic for this bug now.

The real question is still why does it sometimes take that long for tab to be closed. Olivia, do you have some tipps in how to better analyze that? Are there additional logs that we could enable to retrieve further information? Who else from the GeckoView folks could help us here? Thanks.

I'll bring this up in the team meeting. Ted also mentioned this seems reminiscent of bug 2011351 where some dom security features were kicking in on our tests.

Flags: needinfo?(ohall)

Comment hidden (Intermittent Failures Robot)

Pulsebot

Comment 26

•

5 months ago

Pushed by hskupin@mozilla.com: https://github.com/mozilla-firefox/firefox/commit/97fdf3f5acb6 https://hg.mozilla.org/integration/autoland/rev/bf9f4fc77aaa [wdspec] Temporarily mark "test_key_down_closes_browsing_context" as intermittently failing on Android. r=jdescottes

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

Comment 27

•

5 months ago

Lets leave the bug open until we found the root cause of the issue in GeckoView.

status-firefox149: --- → disabled

Keywords: leave-open, test-disabled

Serban Stanca [:SerbanS]

Comment 28

•

5 months ago

bugherder

https://hg.mozilla.org/mozilla-central/rev/bf9f4fc77aaa

Comment hidden (Intermittent Failures Robot)

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

Comment 30

•

4 months ago

(In reply to Olivia Hall [:olivia] from comment #24)

I'll bring this up in the team meeting. Ted also mentioned this seems reminiscent of bug 2011351 where some dom security features were kicking in on our tests.

Olivia, were you already able to discuss this topic? I assume it would be better to file a bug in a GeckoView component?

Assignee: hskupin → nobody

Status: ASSIGNED → NEW

Flags: needinfo?(ohall)

Olivia Hall [:olivia]

Comment 31

•

4 months ago

Thanks, yeah! The best lead we had was if something like bug 2011351 was going on. Please feel free to file a bug in the GeckoView component too.

Flags: needinfo?(ohall)

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

Updated

•

4 months ago

Depends on: 2018901

	no_variant	nofis-noship
android-x86_64/debug		1
android-x86_64/opt	1

	no_variant	nofis	nofis-noship
android-x86_64/debug	3		6
android-x86_64/opt	1	4	1

	no_variant	nofis	nofis-noship
android-x86_64/debug	3	4	1
android-x86_64/opt	1	16	6

	no_variant	nofis	nofis-noship
android-x86_64/debug	9	4	13
android-x86_64/opt	5	20	12

Intermittent Android /webdriver/tests/bidi/input/perform_actions/key.py | test_key_down_closes_browsing_context - Failed: DID NOT RAISE <class 'webdriver.bidi.error.NoSuchFrameException'> | single tracking bug

Repository breakdown:

Table

For more details, see:

Repository breakdown:

Table

For more details, see:

Repository breakdown:

Table

For more details, see:

Repository breakdown:

Table

For more details, see: