Open Bug 1925075 Opened 17 days ago Updated 12 days ago

Intermittent /webdriver/tests/bidi/network/fetch_error/fetch_error.py | test_request_method[HEAD-False] - webdriver.error.TimeoutException: timeout (500): Timed out after 2.0 seconds

Categories

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

defect

Tracking

(Not tracked)

People

(Reporter: intermittent-bug-filer, Unassigned)

References

(Blocks 1 open bug)

Details

(Keywords: intermittent-failure)

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


[task 2024-10-16T16:18:50.518Z] 16:18:50     INFO - TEST-PASS | /webdriver/tests/bidi/network/fetch_error/fetch_error.py | test_navigation_id 
[task 2024-10-16T16:18:50.518Z] 16:18:50     INFO - TEST-PASS | /webdriver/tests/bidi/network/fetch_error/fetch_error.py | test_request_method[GET-False] 
[task 2024-10-16T16:18:50.518Z] 16:18:50     INFO - TEST-UNEXPECTED-FAIL | /webdriver/tests/bidi/network/fetch_error/fetch_error.py | test_request_method[HEAD-False] - webdriver.error.TimeoutException: timeout (500): Timed out after 2.0 seconds
[task 2024-10-16T16:18:50.518Z] 16:18:50     INFO - bidi_session = <webdriver.bidi.client.BidiSession object at 0x000002480BE20B90>
[task 2024-10-16T16:18:50.518Z] 16:18:50     INFO - new_tab = {'context': 'c90d5792-8784-4d1a-a60e-2feccec1b402'}
[task 2024-10-16T16:18:50.518Z] 16:18:50     INFO - wait_for_event = <function wait_for_event.<locals>.wait_for_event at 0x000002480BE33E20>
[task 2024-10-16T16:18:50.518Z] 16:18:50     INFO - wait_for_future_safe = <function wait_for_future_safe.<locals>.wait_for_future_safe at 0x000002480BEE5C60>
[task 2024-10-16T16:18:50.518Z] 16:18:50     INFO - fetch = <function fetch.<locals>.fetch at 0x000002480BEE4360>
[task 2024-10-16T16:18:50.518Z] 16:18:50     INFO - setup_network_test = <function setup_network_test.<locals>._setup_network_test at 0x000002480BEE4A40>
[task 2024-10-16T16:18:50.518Z] 16:18:50     INFO - method = 'HEAD', has_preflight = False
[task 2024-10-16T16:18:50.518Z] 16:18:50     INFO - 
[task 2024-10-16T16:18:50.518Z] 16:18:50     INFO -     @pytest.mark.parametrize(
[task 2024-10-16T16:18:50.519Z] 16:18:50     INFO -         "method, has_preflight",
[task 2024-10-16T16:18:50.519Z] 16:18:50     INFO -         [
[task 2024-10-16T16:18:50.519Z] 16:18:50     INFO -             ("GET", False),
[task 2024-10-16T16:18:50.519Z] 16:18:50     INFO -             ("HEAD", False),
[task 2024-10-16T16:18:50.519Z] 16:18:50     INFO -             ("POST", False),
[task 2024-10-16T16:18:50.519Z] 16:18:50     INFO -             ("OPTIONS", True),
[task 2024-10-16T16:18:50.519Z] 16:18:50     INFO -             ("DELETE", True),
[task 2024-10-16T16:18:50.519Z] 16:18:50     INFO -             ("PATCH", True),
[task 2024-10-16T16:18:50.519Z] 16:18:50     INFO -             ("PUT", True),
[task 2024-10-16T16:18:50.519Z] 16:18:50     INFO -         ],
[task 2024-10-16T16:18:50.519Z] 16:18:50     INFO -     )
[task 2024-10-16T16:18:50.519Z] 16:18:50     INFO -     @pytest.mark.asyncio
[task 2024-10-16T16:18:50.519Z] 16:18:50     INFO -     async def test_request_method(
[task 2024-10-16T16:18:50.519Z] 16:18:50     INFO -         bidi_session,
[task 2024-10-16T16:18:50.519Z] 16:18:50     INFO -         new_tab,
[task 2024-10-16T16:18:50.519Z] 16:18:50     INFO -         wait_for_event,
[task 2024-10-16T16:18:50.519Z] 16:18:50     INFO -         wait_for_future_safe,
[task 2024-10-16T16:18:50.519Z] 16:18:50     INFO -         fetch,
[task 2024-10-16T16:18:50.519Z] 16:18:50     INFO -         setup_network_test,
[task 2024-10-16T16:18:50.519Z] 16:18:50     INFO -         method,
[task 2024-10-16T16:18:50.520Z] 16:18:50     INFO -         has_preflight,
[task 2024-10-16T16:18:50.520Z] 16:18:50     INFO -     ):
[task 2024-10-16T16:18:50.520Z] 16:18:50     INFO -         network_events = await setup_network_test(
[task 2024-10-16T16:18:50.520Z] 16:18:50     INFO -             events=[FETCH_ERROR_EVENT], context=new_tab["context"]
[task 2024-10-16T16:18:50.520Z] 16:18:50     INFO -         )
[task 2024-10-16T16:18:50.520Z] 16:18:50     INFO -         events = network_events[FETCH_ERROR_EVENT]
[task 2024-10-16T16:18:50.520Z] 16:18:50     INFO -     
[task 2024-10-16T16:18:50.520Z] 16:18:50     INFO -         asyncio.ensure_future(fetch(PAGE_INVALID_URL, context=new_tab, method=method))
[task 2024-10-16T16:18:50.520Z] 16:18:50     INFO -     
[task 2024-10-16T16:18:50.520Z] 16:18:50     INFO -         # Requests which might update the server will also fail the CORS preflight
[task 2024-10-16T16:18:50.520Z] 16:18:50     INFO -         # request which uses the OPTIONS method.
[task 2024-10-16T16:18:50.520Z] 16:18:50     INFO -         expected_events = 2 if has_preflight else 1
[task 2024-10-16T16:18:50.520Z] 16:18:50     INFO -     
[task 2024-10-16T16:18:50.520Z] 16:18:50     INFO -         wait = AsyncPoll(bidi_session, timeout=2)
[task 2024-10-16T16:18:50.520Z] 16:18:50     INFO - >       await wait.until(lambda _: len(events) >= expected_events)
[task 2024-10-16T16:18:50.520Z] 16:18:50     INFO - 
[task 2024-10-16T16:18:50.520Z] 16:18:50     INFO - bidi_session = <webdriver.bidi.client.BidiSession object at 0x000002480BE20B90>
[task 2024-10-16T16:18:50.521Z] 16:18:50     INFO - events     = []
[task 2024-10-16T16:18:50.521Z] 16:18:50     INFO - expected_events = 1
[task 2024-10-16T16:18:50.521Z] 16:18:50     INFO - fetch      = <function fetch.<locals>.fetch at 0x000002480BEE4360>
[task 2024-10-16T16:18:50.521Z] 16:18:50     INFO - has_preflight = False
[task 2024-10-16T16:18:50.521Z] 16:18:50     INFO - method     = 'HEAD'
[task 2024-10-16T16:18:50.521Z] 16:18:50     INFO - network_events = {'network.fetchError': []}
[task 2024-10-16T16:18:50.521Z] 16:18:50     INFO - new_tab    = {'context': 'c90d5792-8784-4d1a-a60e-2feccec1b402'}
[task 2024-10-16T16:18:50.521Z] 16:18:50     INFO - setup_network_test = <function setup_network_test.<locals>._setup_network_test at 0x000002480BEE4A40>
[task 2024-10-16T16:18:50.521Z] 16:18:50     INFO - wait       = <tests.support.sync.AsyncPoll object at 0x000002480BECD650>
[task 2024-10-16T16:18:50.521Z] 16:18:50     INFO - wait_for_event = <function wait_for_event.<locals>.wait_for_event at 0x000002480BE33E20>
[task 2024-10-16T16:18:50.521Z] 16:18:50     INFO - wait_for_future_safe = <function wait_for_future_safe.<locals>.wait_for_future_safe at 0x000002480BEE5C60>
[task 2024-10-16T16:18:50.521Z] 16:18:50     INFO - 
[task 2024-10-16T16:18:50.521Z] 16:18:50     INFO - tests\web-platform\tests\webdriver\tests\bidi\network\fetch_error\fetch_error.py:200: 
[task 2024-10-16T16:18:50.521Z] 16:18:50     INFO - _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
[task 2024-10-16T16:18:50.521Z] 16:18:50     INFO - tests\web-platform\tests\webdriver\tests\support\sync.py:279: in until
[task 2024-10-16T16:18:50.521Z] 16:18:50     INFO -     return await poll()
[task 2024-10-16T16:18:50.521Z] 16:18:50     INFO -         condition  = <function test_request_method.<locals>.<lambda> at 0x000002480BEE5580>
[task 2024-10-16T16:18:50.521Z] 16:18:50     INFO -         poll       = <function AsyncPoll.until.<locals>.poll at 0x000002480BEE4860>
[task 2024-10-16T16:18:50.521Z] 16:18:50     INFO -         self       = <tests.support.sync.AsyncPoll object at 0x000002480BECD650>
[task 2024-10-16T16:18:50.521Z] 16:18:50     INFO - _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
[task 2024-10-16T16:18:50.521Z] 16:18:50     INFO - 
[task 2024-10-16T16:18:50.522Z] 16:18:50     INFO -     async def poll():
[task 2024-10-16T16:18:50.522Z] 16:18:50     INFO -         result = None
[task 2024-10-16T16:18:50.522Z] 16:18:50     INFO -         traceback = None
[task 2024-10-16T16:18:50.522Z] 16:18:50     INFO -         start = self.clock.time()
[task 2024-10-16T16:18:50.522Z] 16:18:50     INFO -         end = start + self.timeout
[task 2024-10-16T16:18:50.522Z] 16:18:50     INFO -     
[task 2024-10-16T16:18:50.522Z] 16:18:50     INFO -         while not self.clock.time() >= end:
[task 2024-10-16T16:18:50.522Z] 16:18:50     INFO -             next = self.clock.time() + self.interval
[task 2024-10-16T16:18:50.522Z] 16:18:50     INFO -     
[task 2024-10-16T16:18:50.522Z] 16:18:50     INFO -             try:
[task 2024-10-16T16:18:50.522Z] 16:18:50     INFO -                 result = condition(self.session)
[task 2024-10-16T16:18:50.522Z] 16:18:50     INFO -                 if inspect.isawaitable(result):
[task 2024-10-16T16:18:50.522Z] 16:18:50     INFO -                     result = await result
[task 2024-10-16T16:18:50.522Z] 16:18:50     INFO -             except (KeyboardInterrupt, SystemExit):
[task 2024-10-16T16:18:50.522Z] 16:18:50     INFO -                 raise
[task 2024-10-16T16:18:50.522Z] 16:18:50     INFO -             except self.exceptions:
[task 2024-10-16T16:18:50.523Z] 16:18:50     INFO -                 _, _, traceback = sys.exc_info()
[task 2024-10-16T16:18:50.523Z] 16:18:50     INFO -     
[task 2024-10-16T16:18:50.523Z] 16:18:50     INFO -             # re-adjust the interval depending on how long
[task 2024-10-16T16:18:50.523Z] 16:18:50     INFO -             # the callback took to evaluate the condition
[task 2024-10-16T16:18:50.523Z] 16:18:50     INFO -             interval_new = max(next - self.clock.time(), 0)
[task 2024-10-16T16:18:50.523Z] 16:18:50     INFO -     
[task 2024-10-16T16:18:50.523Z] 16:18:50     INFO -             if result:
[task 2024-10-16T16:18:50.523Z] 16:18:50     INFO -                 return result
[task 2024-10-16T16:18:50.523Z] 16:18:50     INFO -     
[task 2024-10-16T16:18:50.523Z] 16:18:50     INFO -             await asyncio.sleep(interval_new)
[task 2024-10-16T16:18:50.523Z] 16:18:50     INFO -     
[task 2024-10-16T16:18:50.523Z] 16:18:50     INFO -         if self.exc_cls is not None:
[task 2024-10-16T16:18:50.523Z] 16:18:50     INFO -             elapsed = round((self.clock.time() - start), 1)
[task 2024-10-16T16:18:50.523Z] 16:18:50     INFO -             message = f"Timed out after {elapsed} seconds"
[task 2024-10-16T16:18:50.523Z] 16:18:50     INFO -             if self.exc_msg is not None:
[task 2024-10-16T16:18:50.523Z] 16:18:50     INFO -                 message = f"{message} with message: {self.exc_msg}"
[task 2024-10-16T16:18:50.523Z] 16:18:50     INFO - >           raise self.exc_cls(message=message).with_traceback(traceback)
[task 2024-10-16T16:18:50.523Z] 16:18:50     INFO - E           webdriver.error.TimeoutException: timeout (500): Timed out after 2.0 seconds
[task 2024-10-16T16:18:50.523Z] 16:18:50     INFO - 
[task 2024-10-16T16:18:50.524Z] 16:18:50     INFO - condition  = <function test_request_method.<locals>.<lambda> at 0x000002480BEE5580>
[task 2024-10-16T16:18:50.524Z] 16:18:50     INFO - elapsed    = 2.0
[task 2024-10-16T16:18:50.524Z] 16:18:50     INFO - end        = 532.171
[task 2024-10-16T16:18:50.524Z] 16:18:50     INFO - interval_new = 0.10000000000002274
[task 2024-10-16T16:18:50.524Z] 16:18:50     INFO - message    = 'Timed out after 2.0 seconds'
[task 2024-10-16T16:18:50.524Z] 16:18:50     INFO - next       = 532.162
[task 2024-10-16T16:18:50.524Z] 16:18:50     INFO - result     = False
[task 2024-10-16T16:18:50.524Z] 16:18:50     INFO - self       = <tests.support.sync.AsyncPoll object at 0x000002480BECD650>
[task 2024-10-16T16:18:50.524Z] 16:18:50     INFO - start      = 530.171
[task 2024-10-16T16:18:50.524Z] 16:18:50     INFO - traceback  = None
[task 2024-10-16T16:18:50.524Z] 16:18:50     INFO - 
[task 2024-10-16T16:18:50.524Z] 16:18:50     INFO - tests\web-platform\tests\webdriver\tests\support\sync.py:275: TimeoutException
[task 2024-10-16T16:18:50.527Z] 16:18:50     INFO - ........
[task 2024-10-16T16:18:50.527Z] 16:18:50     INFO - TEST-OK | /webdriver/tests/bidi/network/fetch_error/fetch_error.py | took 12013ms
[task 2024-10-16T16:18:50.529Z] 16:18:50     INFO - Restarting browser for new test group
[task 2024-10-16T16:19:00.530Z] 16:19:00  WARNING - Forcibly terminating runner process
[task 2024-10-16T16:19:00.539Z] 16:19:00     INFO - Starting WebDriver: D:\task_172909498231205\fetches\geckodriver.exe --host 127.0.0.1 --port 0 -vv --binary D:\task_172909498231205\build\application\firefox\firefox.exe
[task 2024-10-16T16:19:00.641Z] 16:19:00     INFO - PID 8988 | 1729095540553	geckodriver	INFO	Listening on 127.0.0.1:57067
[task 2024-10-16T16:19:00.643Z] 16:19:00     INFO - Webdriver started successfully.
[task 2024-10-16T16:19:00.644Z] 16:19:00     INFO - Starting runner
[task 2024-10-16T16:19:01.342Z] 16:19:01     INFO - TEST-START | /webdriver/tests/bidi/network/set_cache_behavior/contexts.py
You need to log in before you can comment on or make changes to this bug.