Closed Bug 1838145 Opened 2 years ago Closed 4 months ago

Intermittent Wd | <random> - webdriver.bidi.modules.script.ScriptEvaluateResultException: AbortError: The operation was aborted [fetch request failed]

Categories

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

defect

Tracking

(Not tracked)

RESOLVED INCOMPLETE

People

(Reporter: intermittent-bug-filer, Unassigned)

References

(Depends on 1 open bug)

Details

(Keywords: intermittent-failure)

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


[task 2023-06-13T06:15:42.339Z] 06:15:42     INFO - TEST-PASS | /webdriver/tests/bidi/network/response_completed/response_completed.py | test_load_page_twice 
[task 2023-06-13T06:15:42.346Z] 06:15:42     INFO - TEST-UNEXPECTED-FAIL | /webdriver/tests/bidi/network/response_completed/response_completed.py | test_response_status[101-Switching Protocols] - webdriver.bidi.modules.script.ScriptEvaluateResultException: AbortError: The operation was aborted.
[task 2023-06-13T06:15:42.346Z] 06:15:42     INFO - bidi_session = <webdriver.bidi.client.BidiSession object at 0x0000021637D58340>
[task 2023-06-13T06:15:42.346Z] 06:15:42     INFO - wait_for_event = <function wait_for_event.<locals>.wait_for_event at 0x0000021637D63D30>
[task 2023-06-13T06:15:42.346Z] 06:15:42     INFO - url = <function url.<locals>.url at 0x0000021637E011F0>
[task 2023-06-13T06:15:42.346Z] 06:15:42     INFO - fetch = <function fetch.<locals>.fetch at 0x0000021637D63F70>
[task 2023-06-13T06:15:42.346Z] 06:15:42     INFO - setup_network_test = <function setup_network_test.<locals>._setup_network_test at 0x0000021637E01790>
[task 2023-06-13T06:15:42.346Z] 06:15:42     INFO - status = 101, status_text = 'Switching Protocols'
[task 2023-06-13T06:15:42.346Z] 06:15:42     INFO - 
[task 2023-06-13T06:15:42.346Z] 06:15:42     INFO -     @pytest.mark.parametrize(
[task 2023-06-13T06:15:42.346Z] 06:15:42     INFO -         "status, status_text",
[task 2023-06-13T06:15:42.346Z] 06:15:42     INFO -         HTTP_STATUS_AND_STATUS_TEXT,
[task 2023-06-13T06:15:42.346Z] 06:15:42     INFO -     )
[task 2023-06-13T06:15:42.346Z] 06:15:42     INFO -     @pytest.mark.asyncio
[task 2023-06-13T06:15:42.346Z] 06:15:42     INFO -     async def test_response_status(
[task 2023-06-13T06:15:42.346Z] 06:15:42     INFO -         bidi_session, wait_for_event, url, fetch, setup_network_test, status, status_text
[task 2023-06-13T06:15:42.346Z] 06:15:42     INFO -     ):
[task 2023-06-13T06:15:42.346Z] 06:15:42     INFO -         status_url = url(
[task 2023-06-13T06:15:42.346Z] 06:15:42     INFO -             f"/webdriver/tests/support/http_handlers/status.py?status={status}&nocache={RESPONSE_COMPLETED_EVENT}"
[task 2023-06-13T06:15:42.346Z] 06:15:42     INFO -         )
[task 2023-06-13T06:15:42.347Z] 06:15:42     INFO -     
[task 2023-06-13T06:15:42.347Z] 06:15:42     INFO -         network_events = await setup_network_test(events=[RESPONSE_COMPLETED_EVENT])
[task 2023-06-13T06:15:42.347Z] 06:15:42     INFO -         events = network_events[RESPONSE_COMPLETED_EVENT]
[task 2023-06-13T06:15:42.347Z] 06:15:42     INFO -     
[task 2023-06-13T06:15:42.347Z] 06:15:42     INFO -         on_response_completed = wait_for_event(RESPONSE_COMPLETED_EVENT)
[task 2023-06-13T06:15:42.347Z] 06:15:42     INFO - >       await fetch(status_url)
[task 2023-06-13T06:15:42.347Z] 06:15:42     INFO - 
[task 2023-06-13T06:15:42.347Z] 06:15:42     INFO - bidi_session = <webdriver.bidi.client.BidiSession object at 0x0000021637D58340>
[task 2023-06-13T06:15:42.347Z] 06:15:42     INFO - events     = []
[task 2023-06-13T06:15:42.348Z] 06:15:42     INFO - fetch      = <function fetch.<locals>.fetch at 0x0000021637D63F70>
[task 2023-06-13T06:15:42.348Z] 06:15:42     INFO - network_events = {'network.responseCompleted': []}
[task 2023-06-13T06:15:42.348Z] 06:15:42     INFO - on_response_completed = <Future pending>
[task 2023-06-13T06:15:42.348Z] 06:15:42     INFO - setup_network_test = <function setup_network_test.<locals>._setup_network_test at 0x0000021637E01790>
[task 2023-06-13T06:15:42.348Z] 06:15:42     INFO - status     = 101
[task 2023-06-13T06:15:42.348Z] 06:15:42     INFO - status_text = 'Switching Protocols'
[task 2023-06-13T06:15:42.348Z] 06:15:42     INFO - status_url = 'http://web-platform.test:8000/webdriver/tests/support/http_handlers/status.py?status=101&nocache=network.responseCompleted'
[task 2023-06-13T06:15:42.348Z] 06:15:42     INFO - url        = <function url.<locals>.url at 0x0000021637E011F0>
[task 2023-06-13T06:15:42.348Z] 06:15:42     INFO - wait_for_event = <function wait_for_event.<locals>.wait_for_event at 0x0000021637D63D30>
[task 2023-06-13T06:15:42.348Z] 06:15:42     INFO - 
[task 2023-06-13T06:15:42.348Z] 06:15:42     INFO - tests\web-platform\tests\webdriver\tests\bidi\network\response_completed\response_completed.py:144: 
[task 2023-06-13T06:15:42.348Z] 06:15:42     INFO - _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
[task 2023-06-13T06:15:42.348Z] 06:15:42     INFO - tests\web-platform\tests\webdriver\tests\bidi\network\conftest.py:30: in fetch
[task 2023-06-13T06:15:42.348Z] 06:15:42     INFO -     await bidi_session.script.evaluate(
[task 2023-06-13T06:15:42.348Z] 06:15:42     INFO -         bidi_session = <webdriver.bidi.client.BidiSession object at 0x0000021637D58340>
[task 2023-06-13T06:15:42.348Z] 06:15:42     INFO -         configuration = {'browser': {'args': ['--profile',
[task 2023-06-13T06:15:42.348Z] 06:15:42     INFO -                       'C:\\Users\\task_168663216796581\\AppData\\Local\\Temp\\tmpn9bhwnxd.mozrunner'],
[task 2023-06-13T06:15:42.348Z] 06:15:42     INFO -              'binary': 'Z:\\task_168663216796581\\build\\application\\firefox\\firefox.exe'},
[task 2023-06-13T06:15:42.348Z] 06:15:42     INFO -  'capabilities': {'moz:firefoxOptions': {'args': ['--profile',
[task 2023-06-13T06:15:42.348Z] 06:15:42     INFO -                                                   'C:\\Users\\task_168663216796581\\AppData\\Local\\Temp\\tmpn9bhwnxd.mozrunner']}},
[task 2023-06-13T06:15:42.348Z] 06:15:42     INFO -  'host': '127.0.0.1',
[task 2023-06-13T06:15:42.348Z] 06:15:42     INFO -  'port': 49745,
[task 2023-06-13T06:15:42.348Z] 06:15:42     INFO -  'timeout_multiplier': 1,
[task 2023-06-13T06:15:42.349Z] 06:15:42     INFO -  'webdriver': {'args': ['-vv',
[task 2023-06-13T06:15:42.349Z] 06:15:42     INFO -                         '--binary',
[task 2023-06-13T06:15:42.349Z] 06:15:42     INFO -                         'Z:\\task_168663216796581\\build\\application\\firefox\\firefox.exe'],
[task 2023-06-13T06:15:42.349Z] 06:15:42     INFO -                'binary': 'Z:\\task_168663216796581\\fetches\\geckodriver.exe'}}
[task 2023-06-13T06:15:42.349Z] 06:15:42     INFO -         context    = {'children': [],
[task 2023-06-13T06:15:42.349Z] 06:15:42     INFO -  'context': '0073754f-11d1-4265-a22b-c93fd60d87d4',
[task 2023-06-13T06:15:42.349Z] 06:15:42     INFO -  'parent': None,
[task 2023-06-13T06:15:42.349Z] 06:15:42     INFO -  'url': 'http://web-platform.test:8000/webdriver/tests/bidi/network/support/empty.html'}
[task 2023-06-13T06:15:42.349Z] 06:15:42     INFO -         headers    = None
[task 2023-06-13T06:15:42.349Z] 06:15:42     INFO -         headers_arg = ''
[task 2023-06-13T06:15:42.349Z] 06:15:42     INFO -         method     = 'GET'
[task 2023-06-13T06:15:42.349Z] 06:15:42     INFO -         method_arg = "method: 'GET',"
[task 2023-06-13T06:15:42.349Z] 06:15:42     INFO -         timeout_in_seconds = 3
[task 2023-06-13T06:15:42.349Z] 06:15:42     INFO -         url        = 'http://web-platform.test:8000/webdriver/tests/support/http_handlers/status.py?status=101&nocache=network.responseCompleted'
[task 2023-06-13T06:15:42.349Z] 06:15:42     INFO - tests\web-platform\tests\tools\webdriver\webdriver\bidi\modules\_module.py:76: in inner
[task 2023-06-13T06:15:42.349Z] 06:15:42     INFO -     result = result_fn(self, result)
[task 2023-06-13T06:15:42.349Z] 06:15:42     INFO -         cmd_name   = 'script.evaluate'
[task 2023-06-13T06:15:42.349Z] 06:15:42     INFO -         future     = <Future finished result={'exceptionDetails': {'columnNumber': 22, 'exception': {'type': 'error'}, 'lineNumber': 8, 'stackTrace': {'callFrames': [{'columnNumber': 22, 'functionName': '', 'lineNumber': 8, 'url': 'http://web-p...rt/empty.html'}]}, ...}, 'realm': '7e7b8061-e0d...-e8054baba8ed', 'type': 'exception'}>
[task 2023-06-13T06:15:42.349Z] 06:15:42     INFO -         kwargs     = {'await_promise': True,
[task 2023-06-13T06:15:42.349Z] 06:15:42     INFO -  'expression': '\n'
[task 2023-06-13T06:15:42.349Z] 06:15:42     INFO -                '                 {\n'
[task 2023-06-13T06:15:42.349Z] 06:15:42     INFO -                '                   const controller = new AbortController();\n'
[task 2023-06-13T06:15:42.350Z] 06:15:42     INFO -                '                   setTimeout(() => controller.abort(), '
[task 2023-06-13T06:15:42.350Z] 06:15:42     INFO -                '3000);\n'
[task 2023-06-13T06:15:42.350Z] 06:15:42     INFO -                '                   '
[task 2023-06-13T06:15:42.350Z] 06:15:42     INFO -                'fetch("http://web-platform.test:8000/webdriver/tests/support/http_handlers/status.py?status=101&nocache=network.responseCompleted", '
[task 2023-06-13T06:15:42.350Z] 06:15:42     INFO -                '{\n'
[task 2023-06-13T06:15:42.350Z] 06:15:42     INFO -                "                     method: 'GET',\n"
[task 2023-06-13T06:15:42.350Z] 06:15:42     INFO -                '                     \n'
[task 2023-06-13T06:15:42.350Z] 06:15:42     INFO -                '                     signal: controller.signal\n'
[task 2023-06-13T06:15:42.350Z] 06:15:42     INFO -                '                   }).then(response => response.text());\n'
[task 2023-06-13T06:15:42.350Z] 06:15:42     INFO -                '                 }',
[task 2023-06-13T06:15:42.350Z] 06:15:42     INFO -  'target': {'context': '0073754f-11d1-4265-a22b-c93fd60d87d4'}}
[task 2023-06-13T06:15:42.350Z] 06:15:42     INFO -         mod_name   = 'script'
[task 2023-06-13T06:15:42.350Z] 06:15:42     INFO -         name       = 'evaluate'
[task 2023-06-13T06:15:42.350Z] 06:15:42     INFO -         owner      = <class 'webdriver.bidi.modules.script.Script'>
[task 2023-06-13T06:15:42.350Z] 06:15:42     INFO -         params     = {'awaitPromise': True,
[task 2023-06-13T06:15:42.350Z] 06:15:42     INFO -  'expression': '\n'
[task 2023-06-13T06:15:42.350Z] 06:15:42     INFO -                '                 {\n'
[task 2023-06-13T06:15:42.350Z] 06:15:42     INFO -                '                   const controller = new AbortController();\n'
[task 2023-06-13T06:15:42.350Z] 06:15:42     INFO -                '                   setTimeout(() => controller.abort(), '
[task 2023-06-13T06:15:42.350Z] 06:15:42     INFO -                '3000);\n'
[task 2023-06-13T06:15:42.350Z] 06:15:42     INFO -                '                   '
[task 2023-06-13T06:15:42.350Z] 06:15:42     INFO -                'fetch("http://web-platform.test:8000/webdriver/tests/support/http_handlers/status.py?status=101&nocache=network.responseCompleted", '
[task 2023-06-13T06:15:42.351Z] 06:15:42     INFO -                '{\n'
[task 2023-06-13T06:15:42.351Z] 06:15:42     INFO -                "                     method: 'GET',\n"
[task 2023-06-13T06:15:42.351Z] 06:15:42     INFO -                '                     \n'
[task 2023-06-13T06:15:42.351Z] 06:15:42     INFO -                '                     signal: controller.signal\n'
[task 2023-06-13T06:15:42.351Z] 06:15:42     INFO -                '                   }).then(response => response.text());\n'
[task 2023-06-13T06:15:42.351Z] 06:15:42     INFO -                '                 }',
[task 2023-06-13T06:15:42.351Z] 06:15:42     INFO -  'target': {'context': '0073754f-11d1-4265-a22b-c93fd60d87d4'}}
[task 2023-06-13T06:15:42.351Z] 06:15:42     INFO -         params_fn  = <function Script.evaluate at 0x0000021637C361F0>
[task 2023-06-13T06:15:42.351Z] 06:15:42     INFO -         raw_result = False
[task 2023-06-13T06:15:42.351Z] 06:15:42     INFO -         result     = {'exceptionDetails': {'columnNumber': 22,
[task 2023-06-13T06:15:42.351Z] 06:15:42     INFO -                       'exception': {'type': 'error'},
[task 2023-06-13T06:15:42.351Z] 06:15:42     INFO -                       'lineNumber': 8,
[task 2023-06-13T06:15:42.351Z] 06:15:42     INFO -                       'stackTrace': {'callFrames': [{'columnNumber': 22,
[task 2023-06-13T06:15:42.351Z] 06:15:42     INFO -                                                      'functionName': '',
[task 2023-06-13T06:15:42.351Z] 06:15:42     INFO -                                                      'lineNumber': 8,
[task 2023-06-13T06:15:42.351Z] 06:15:42     INFO -                                                      'url': 'http://web-platform.test:8000/webdriver/tests/bidi/network/support/empty.html'}]},
[task 2023-06-13T06:15:42.351Z] 06:15:42     INFO -                       'text': 'AbortError: The operation was aborted. '},
[task 2023-06-13T06:15:42.351Z] 06:15:42     INFO -  'realm': '7e7b8061-e0d2-4dd8-9cd4-e8054baba8ed',
[task 2023-06-13T06:15:42.351Z] 06:15:42     INFO -  'type': 'exception'}
[task 2023-06-13T06:15:42.351Z] 06:15:42     INFO -         result_fn  = <function Script._evaluate at 0x0000021637C36280>
[task 2023-06-13T06:15:42.351Z] 06:15:42     INFO -         self       = <webdriver.bidi.modules.script.Script object at 0x0000021637D589A0>
[task 2023-06-13T06:15:42.351Z] 06:15:42     INFO - _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
[task 2023-06-13T06:15:42.352Z] 06:15:42     INFO - 
[task 2023-06-13T06:15:42.352Z] 06:15:42     INFO - self = <webdriver.bidi.modules.script.Script object at 0x0000021637D589A0>
[task 2023-06-13T06:15:42.352Z] 06:15:42     INFO - result = {'exceptionDetails': {'columnNumber': 22, 'exception': {'type': 'error'}, 'lineNumber': 8, 'stackTrace': {'callFrames'.../tests/bidi/network/support/empty.html'}]}, ...}, 'realm': '7e7b8061-e0d2-4dd8-9cd4-e8054baba8ed', 'type': 'exception'}
[task 2023-06-13T06:15:42.352Z] 06:15:42     INFO - 
[task 2023-06-13T06:15:42.352Z] 06:15:42     INFO -     @evaluate.result
[task 2023-06-13T06:15:42.352Z] 06:15:42     INFO -     def _evaluate(self, result: Mapping[str, Any]) -> Any:
[task 2023-06-13T06:15:42.352Z] 06:15:42     INFO -         assert "type" in result
[task 2023-06-13T06:15:42.352Z] 06:15:42     INFO -     
[task 2023-06-13T06:15:42.352Z] 06:15:42     INFO -         if result["type"] == "success":
[task 2023-06-13T06:15:42.352Z] 06:15:42     INFO -             return result["result"]
[task 2023-06-13T06:15:42.352Z] 06:15:42     INFO -         elif result["type"] == "exception":
[task 2023-06-13T06:15:42.353Z] 06:15:42     INFO - >           raise ScriptEvaluateResultException(result)
[task 2023-06-13T06:15:42.353Z] 06:15:42     INFO - E           webdriver.bidi.modules.script.ScriptEvaluateResultException: AbortError: The operation was aborted. 
[task 2023-06-13T06:15:42.353Z] 06:15:42     INFO - E           
[task 2023-06-13T06:15:42.353Z] 06:15:42     INFO - E           Stacktrace:
[task 2023-06-13T06:15:42.353Z] 06:15:42     INFO - E           
[task 2023-06-13T06:15:42.353Z] 06:15:42     INFO - E           eval code@http://web-platform.test:8000/webdriver/tests/bidi/network/support/empty.html:8:22
[task 2023-06-13T06:15:42.353Z] 06:15:42     INFO - 
[task 2023-06-13T06:15:42.353Z] 06:15:42     INFO - result     = {'exceptionDetails': {'columnNumber': 22,
[task 2023-06-13T06:15:42.353Z] 06:15:42     INFO -                       'exception': {'type': 'error'},
[task 2023-06-13T06:15:42.353Z] 06:15:42     INFO -                       'lineNumber': 8,
[task 2023-06-13T06:15:42.353Z] 06:15:42     INFO -                       'stackTrace': {'callFrames': [{'columnNumber': 22,
[task 2023-06-13T06:15:42.353Z] 06:15:42     INFO -                                                      'functionName': '',
[task 2023-06-13T06:15:42.353Z] 06:15:42     INFO -                                                      'lineNumber': 8,
[task 2023-06-13T06:15:42.353Z] 06:15:42     INFO -                                                      'url': 'http://web-platform.test:8000/webdriver/tests/bidi/network/support/empty.html'}]},
[task 2023-06-13T06:15:42.353Z] 06:15:42     INFO -                       'text': 'AbortError: The operation was aborted. '},
[task 2023-06-13T06:15:42.353Z] 06:15:42     INFO -  'realm': '7e7b8061-e0d2-4dd8-9cd4-e8054baba8ed',
[task 2023-06-13T06:15:42.353Z] 06:15:42     INFO -  'type': 'exception'}
[task 2023-06-13T06:15:42.353Z] 06:15:42     INFO - self       = <webdriver.bidi.modules.script.Script object at 0x0000021637D589A0>
[task 2023-06-13T06:15:42.353Z] 06:15:42     INFO - 
[task 2023-06-13T06:15:42.353Z] 06:15:42     INFO - tests\web-platform\tests\tools\webdriver\webdriver\bidi\modules\script.py:189: ScriptEvaluateResultException
[task 2023-06-13T06:15:42.354Z] 06:15:42     INFO - PID 9788 | 1686636940715	RemoteAgent	DEBUG	WebDriverBiDiConnection bba797f6-a971-4f66-b277-a2ce173531de <- {"id":227,"result":{}}
[task 2023-06-13T06:15:42.355Z] 06:15:42     INFO - .
[task 2023-06-13T06:15:42.355Z] 06:15:42     INFO - PID 9788 | 1686636940715	RemoteAgent	DEBUG	WebDriverBiDiConnection bba797f6-a971-4f66-b277-a2ce173531de -> {"id":228,"method":"session.subscribe","params":{"events":["network.responseCompleted"]}}
[task 2023-06-13T06:15:42.356Z] 06:15:42     INFO - .
[task 2023-06-13T06:15:42.356Z] 06:15:42     INFO - PID 9788 | 1686636940715	RemoteAgent	TRACE	Module root/session.jsm found for ROOT
[task 2023-06-13T06:15:42.357Z] 06:15:42     INFO - .
[task 2023-06-13T06:15:42.357Z] 06:15:42     INFO - PID 9788 | 1686636940715	RemoteAgent	TRACE	Received command session.subscribe for destination ROOT
[task 2023-06-13T06:15:42.358Z] 06:15:42     INFO - .
[task 2023-06-13T06:15:42.358Z] 06:15:42     INFO - PID 9788 | 1686636940715	RemoteAgent	TRACE	Module root/session.jsm found for ROOT
[task 2023-06-13T06:15:42.359Z] 06:15:42     INFO - .
[task 2023-06-13T06:15:42.360Z] 06:15:42     INFO - PID 9788 | 1686636940716	RemoteAgent	TRACE	Module root/network.jsm found for ROOT
[task 2023-06-13T06:15:42.360Z] 06:15:42     INFO - .
[task 2023-06-13T06:15:42.360Z] 06:15:42     INFO - PID 9788 | 1686636940717	RemoteAgent	TRACE	Module windowglobal-in-root/network.jsm not found for WINDOW_GLOBAL
[task 2023-06-13T06:15:42.362Z] 06:15:42     INFO - .
[task 2023-06-13T06:15:42.362Z] 06:15:42     INFO - PID 9788 | 1686636940717	RemoteAgent	TRACE	Module windowglobal/network.jsm not found for WINDOW_GLOBAL
[task 2023-06-13T06:15:42.363Z] 06:15:42     INFO - .
[task 2023-06-13T06:15:42.364Z] 06:15:42     INFO - PID 9788 | 1686636940717	RemoteAgent	TRACE	Module root/network.jsm found for ROOT
[task 2023-06-13T06:15:42.364Z] 06:15:42     INFO - .
[task 2023-06-13T06:15:42.365Z] 06:15:42     INFO - PID 9788 | 1686636940717	RemoteAgent	TRACE	Received command network._applySessionData for destination ROOT
[task 2023-06-13T06:15:42.365Z] 06:15:42     INFO - .
[task 2023-06-13T06:15:42.366Z] 06:15:42     INFO - PID 9788 | 1686636940717	RemoteAgent	TRACE	Module root/network.jsm found for ROOT
[task 2023-06-13T06:15:42.366Z] 06:15:42     INFO - .
[task 2023-06-13T06:15:42.366Z] 06:15:42     INFO - PID 9788 | 1686636940717	RemoteAgent	DEBUG	WebDriverBiDiConnection bba797f6-a971-4f66-b277-a2ce173531de <- {"id":228,"result":{}}
[task 2023-06-13T06:15:42.368Z] 06:15:42     INFO - .
[task 2023-06-13T06:15:42.368Z] 06:15:42     INFO - PID 9788 | 1686636940719	RemoteAgent	DEBUG	WebDriverBiDiConnection bba797f6-a971-4f66-b277-a2ce173531de -> {"id":229,"method":"script.evaluate","params":{"expression":"\n                 {\n                   const controller = new AbortController();\n                   setTimeout(() => controll ...   \n                     signal: controller.signal\n                   }).then(response => response.text());\n                 }","target":{"context":"0073754f-11d1-4265-a22b-c93fd60d87d4"},"awaitPromise":true}}
[task 2023-06-13T06:15:42.370Z] 06:15:42     INFO - .
[task 2023-06-13T06:15:42.370Z] 06:15:42     INFO - PID 9788 | 1686636940719	RemoteAgent	TRACE	Module root/script.jsm found for ROOT
[task 2023-06-13T06:15:42.371Z] 06:15:42     INFO - .
[task 2023-06-13T06:15:42.371Z] 06:15:42     INFO - PID 9788 | 1686636940719	RemoteAgent	TRACE	Received command script.evaluate for destination ROOT
[task 2023-06-13T06:15:42.372Z] 06:15:42     INFO - .
[task 2023-06-13T06:15:42.372Z] 06:15:42     INFO - PID 9788 | 1686636940719	RemoteAgent	TRACE	Module root/script.jsm found for ROOT
[task 2023-06-13T06:15:42.373Z] 06:15:42     INFO - .
[task 2023-06-13T06:15:42.374Z] 06:15:42     INFO - PID 9788 | 1686636940719	RemoteAgent	TRACE	Received command script.evaluateExpression for destination WINDOW_GLOBAL
[task 2023-06-13T06:15:42.374Z] 06:15:42     INFO - .
[task 2023-06-13T06:15:42.375Z] 06:15:42     INFO - PID 9788 | 1686636940719	RemoteAgent	TRACE	Module windowglobal/script.jsm found for WINDOW_GLOBAL
[task 2023-06-13T06:15:42.376Z] 06:15:42     INFO - .
[task 2023-06-13T06:15:42.376Z] 06:15:42     INFO - PID 9788 | 1686636940719	RemoteAgent	TRACE	Module windowglobal/script.jsm found for WINDOW_GLOBAL
[task 2023-06-13T06:15:42.377Z] 06:15:42     INFO - .
[task 2023-06-13T06:15:42.377Z] 06:15:42     INFO - PID 9788 | 1686636940726	RemoteAgent	DEBUG	WebDriverBiDiConnection bba797f6-a971-4f66-b277-a2ce173531de <- {"id":229,"result":{"realm":"17ee6844-1f03-4d38-8612-2f4b17361c5c","type":"success","result":{"type":"string","value":"HTTP Response Status"}}}
[task 2023-06-13T06:15:42.380Z] 06:15:42     INFO - .
[task 2023-06-13T06:15:42.380Z] 06:15:42     INFO - PID 9788 | 1686636940727	RemoteAgent	DEBUG	WebDriverBiDiConnection bba797f6-a971-4f66-b277-a2ce173531de <- {"method":"network.responseCompleted","params":{"context":"0073754f-11d1-4265-a22b-c93fd60d87d4","navigation":null,"redirectCount":0,"request":{"bodySize":null,"cookies":[],"headers":[{"name":"Host","value":"web-platform.test:8000"},{"name":"User-Agent","value":"Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:109.0) Gecko/20100101 Firefox/116.0"},{"name":"Accept","value":"*/*"},{"name":"Accept-Language","value":"en-US,en;q=0.5"},{"name":"Accept-Encoding","value":"gzip, deflate"},{"name":"Referer","value":"http://web-platform.test:8000/webdriver/tests/bidi/network/support/empty.html"},{"name":"Connection","value":"keep-alive"}],"headersSize":424,"method":"GET","request":"77","timings":{"timeOrigin":0,"requestTime":1686636940720000,"redirectStart":0,"redirectEnd":0,"fetchStart":1686636940720553,"dnsStart":1686636940720553,"dnsEnd":1686636940721099,"connectStart":1686636940721651,"connectEnd":1686636940721878,"tlsStart":0,"tlsEnd":1686636940721878,"requestStart":1686636940721962,"responseStart":1686636940723421,"responseEnd":1686636940723688},"url":"http://web-platform.test:8000/webdriver/tests/support/http_handlers/status.py?status=501&nocache=network.responseCompleted"},"timestamp":1686636940727,"response":{"bodySize":20,"content":{"size":20},"headersSize":151,"url":"http://web-platform.test:8000/webdriver/tests/support/http_handlers/status.py?status=501&nocache=network.responseCompleted","bytesReceived":171,"fromCache":false,"headers":[{"name":"Content-Type","value":"text/plain"},{"name":"Server","value":"BaseHTTP/0.6 Python/3.9.10"},{"name":"Date","value":"Tue, 13 Jun 2023 06:15:40 GMT"},{"name":"Content-Length","value":"20"}],"mimeType":"text/plain","protocol":"http/1.1","status":501,"statusText":"Not Implemented"}}}
[task 2023-06-13T06:15:42.381Z] 06:15:42     INFO - .
[task 2023-06-13T06:15:42.382Z] 06:15:42     INFO - PID 9788 | 1686636940729	RemoteAgent	DEBUG	WebDriverBiDiConnection bba797f6-a971-4f66-b277-a2ce173531de -> {"id":230,"method":"session.unsubscribe","params":{"events":["network.responseCompleted"]}}
[task 2023-06-13T06:15:42.383Z] 06:15:42     INFO - .
[task 2023-06-13T06:15:42.383Z] 06:15:42     INFO - PID 9788 | 1686636940729	RemoteAgent	TRACE	Module root/session.jsm found for ROOT
[task 2023-06-13T06:15:42.384Z] 06:15:42     INFO - .
[task 2023-06-13T06:15:42.384Z] 06:15:42     INFO - PID 9788 | 1686636940729	RemoteAgent	TRACE	Received command session.unsubscribe for destination ROOT
[task 2023-06-13T06:15:42.385Z] 06:15:42     INFO - .
[task 2023-06-13T06:15:42.385Z] 06:15:42     INFO - PID 9788 | 1686636940729	RemoteAgent	TRACE	Module root/session.jsm found for ROOT
[task 2023-06-13T06:15:42.386Z] 06:15:42     INFO - .
[task 2023-06-13T06:15:42.386Z] 06:15:42     INFO - PID 9788 | 1686636940729	RemoteAgent	TRACE	Module root/network.jsm found for ROOT
[task 2023-06-13T06:15:42.387Z] 06:15:42     INFO - .
[task 2023-06-13T06:15:42.387Z] 06:15:42     INFO - PID 9788 | 1686636940731	RemoteAgent	TRACE	Module windowglobal-in-root/network.jsm not found for WINDOW_GLOBAL
[task 2023-06-13T06:15:42.388Z] 06:15:42     INFO - .
[task 2023-06-13T06:15:42.388Z] 06:15:42     INFO - PID 9788 | 1686636940731	RemoteAgent	TRACE	Module windowglobal/network.jsm not found for WINDOW_GLOBAL
[task 2023-06-13T06:15:42.390Z] 06:15:42     INFO - .
[task 2023-06-13T06:15:42.390Z] 06:15:42     INFO - PID 9788 | 1686636940731	RemoteAgent	TRACE	Module root/network.jsm found for ROOT
[task 2023-06-13T06:15:42.391Z] 06:15:42     INFO - .
[task 2023-06-13T06:15:42.391Z] 06:15:42     INFO - PID 9788 | 1686636940731	RemoteAgent	TRACE	Received command network._applySessionData for destination ROOT
[task 2023-06-13T06:15:42.392Z] 06:15:42     INFO - .
[task 2023-06-13T06:15:42.392Z] 06:15:42     INFO - PID 9788 | 1686636940731	RemoteAgent	TRACE	Module root/network.jsm found for ROOT
[task 2023-06-13T06:15:42.393Z] 06:15:42     INFO - .
[task 2023-06-13T06:15:42.393Z] 06:15:42     INFO - PID 9788 | 1686636940731	RemoteAgent	DEBUG	WebDriverBiDiConnection bba797f6-a971-4f66-b277-a2ce173531de <- {"id":230,"result":{}}
[task 2023-06-13T06:15:42.394Z] 06:15:42     INFO - .
[task 2023-06-13T06:15:42.395Z] 06:15:42     INFO - PID 9788 | 1686636940733	RemoteAgent	DEBUG	WebDriverBiDiConnection bba797f6-a971-4f66-b277-a2ce173531de closed
[task 2023-06-13T06:15:42.395Z] 06:15:42     INFO - .
[task 2023-06-13T06:15:42.395Z] 06:15:42     INFO - PID 9788 | 1686636940734	webdriver::server	DEBUG	-> POST /session/b23d4c8d-ad61-458c-82dd-05e14161d9d4/timeouts {"implicit": 0}
[task 2023-06-13T06:15:42.397Z] 06:15:42     INFO - .
[task 2023-06-13T06:15:42.397Z] 06:15:42     INFO - PID 9788 | 1686636940734	Marionette	DEBUG	0 -> [0,516,"WebDriver:SetTimeouts",{"implicit":0}]
[task 2023-06-13T06:15:42.398Z] 06:15:42     INFO - .
[task 2023-06-13T06:15:42.398Z] 06:15:42     INFO - PID 9788 | 1686636940734	Marionette	DEBUG	0 <- [1,516,null,{"value":null}]
[task 2023-06-13T06:15:42.399Z] 06:15:42     INFO - .
[task 2023-06-13T06:15:42.400Z] 06:15:42     INFO - PID 9788 | 1686636940734	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2023-06-13T06:15:42.401Z] 06:15:42     INFO - .
[task 2023-06-13T06:15:42.401Z] 06:15:42     INFO - PID 9788 | 1686636940735	webdriver::server	DEBUG	-> POST /session/b23d4c8d-ad61-458c-82dd-05e14161d9d4/timeouts {"pageLoad": 300000}
[task 2023-06-13T06:15:42.402Z] 06:15:42     INFO - .
[task 2023-06-13T06:15:42.402Z] 06:15:42     INFO - PID 9788 | 1686636940736	Marionette	DEBUG	0 -> [0,517,"WebDriver:SetTimeouts",{"pageLoad":300000}]
[task 2023-06-13T06:15:42.403Z] 06:15:42     INFO - .
[task 2023-06-13T06:15:42.403Z] 06:15:42     INFO - PID 9788 | 1686636940736	Marionette	DEBUG	0 <- [1,517,null,{"value":null}]
[task 2023-06-13T06:15:42.404Z] 06:15:42     INFO - .
[task 2023-06-13T06:15:42.404Z] 06:15:42     INFO - PID 9788 | 1686636940736	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2023-06-13T06:15:42.406Z] 06:15:42     INFO - .
[task 2023-06-13T06:15:42.406Z] 06:15:42     INFO - PID 9788 | 1686636940737	webdriver::server	DEBUG	-> POST /session/b23d4c8d-ad61-458c-82dd-05e14161d9d4/timeouts {"script": 30000}
[task 2023-06-13T06:15:42.407Z] 06:15:42     INFO - PID 9788 | 1686636940738	Marionette	DEBUG	0 -> [0,518,"WebDriver:SetTimeouts",{"script":30000}]

Here the fetch request failed after 3s to load a page as served by wptserve. Maybe related to bug 1832294.

See Also: → 1832294

A fix for bug 1837949 might help here.

Depends on: 1837949
See Also: → 1832294
Summary: Intermittent /webdriver/tests/bidi/network/response_completed/response_completed.py | test_response_status[101-Switching Protocols] - webdriver.bidi.modules.script.ScriptEvaluateResultException: AbortError: The operation was aborted. → Intermittent /webdriver/tests/bidi/network/response_completed/response_completed.py | test_response_status[101-Switching Protocols] - webdriver.bidi.modules.script.ScriptEvaluateResultException: AbortError: The operation was aborted [fetch request failed]
See Also: → 1849207

This affects multiple tests. As such lets make it a general bug.

Summary: Intermittent /webdriver/tests/bidi/network/response_completed/response_completed.py | test_response_status[101-Switching Protocols] - webdriver.bidi.modules.script.ScriptEvaluateResultException: AbortError: The operation was aborted [fetch request failed] → Intermittent Wd | <random> - webdriver.bidi.modules.script.ScriptEvaluateResultException: AbortError: The operation was aborted [fetch request failed]
Duplicate of this bug: 1849207

I wonder if that is related to the other navigation issues that we have and timing out (bug 1825501). Maybe some kind of overlapping navigation or network issue.

See Also: → 1825501
Duplicate of this bug: 1866185
Status: NEW → RESOLVED
Closed: 1 year ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 1 year ago1 year ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---

The recent failures are android only. We always seem to hang on the last fetch call. We receive the beforeRequestSent event, it's not marked as blocked, but the evaluate call still gets aborted after 12s (3s default fetch timeout * 4 for the platform multiplier).

Maybe we have too many requests in progress?

This is actually a recent spike for Android 14 jobs only. Those were enabled on August 26th in CI via bug 1985020 when these failures started to happen. The Android 7 jobs, which are still running, do not show this failure. I wonder if we should track that as a separate bug - at least for the fix.

add_intercept.py only generates a few blocked requests, so if we are indeed hitting network limitations it's a bit worrying. There are only 5 blocked requests (taking parametrization into account) before we hit the request which usually hangs.

I pushed to try a version which attempts to resume all requests, let's see if at least that seems to improve the situation.

Quick update here:

  • resuming requests allows to fix the issue
  • stress test using requests blocked in the beforeRequestSent phase doesn't trigger the issue

I am pushing another stress test using the responseStarted phase, I suspect we have a similar issue compared to Bug 1966494. Now in theory this shouldn't happen because we enable rcwn (race-cache-with-network) for WebDriver BiDi (bug 1968242). But based on the name, I think the feature might not always decide to hit the network rather than hitting the cache, and that's probably what we are seeing here.

Valentin: quick summary of the situation here. We have a first request to some_url which gets suspended in http-on-examine-response. Then we issue a second request to some_url which is not suspended by us. It seems that on Android 14, even with rcwn enabled, we still hit the cache an reuse the suspended response from the first request. Is that possible?

See Also: → 1966494

(forgot to ni Valentin, see message above)

Flags: needinfo?(valentin.gosu)

I can confirm that the wdspec test I wrote to highlight the rcwn issue back in https://bugzilla.mozilla.org/show_bug.cgi?id=1966494#c4 fails intermittently with Android 14.0, but not with 7.0.

We should stick to unique URLs for the tests which exercise blocking to avoid cache issues.

Depends on: 1988681

It seems that on Android 14, even with rcwn enabled, we still hit the cache an reuse the suspended response from the first request. Is that possible?

Yes, if Android 14 has faster IO, then the cache response would be returned faster leading to us using the cache response even if racing is enabled.

Flags: needinfo?(valentin.gosu)
Status: REOPENED → RESOLVED
Closed: 1 year ago4 months ago
Resolution: --- → INCOMPLETE
You need to log in before you can comment on or make changes to this bug.