Closed
Bug 1910280
Opened 3 months ago
Closed 1 month ago
Intermittent /webdriver/tests/bidi/network/fetch_error/fetch_error.py | test_request_method[PATCH-True] - webdriver.error.TimeoutException: timeout (500): Timed out after 2.1 seconds
Categories
(Remote Protocol :: WebDriver BiDi, defect, P5)
Remote Protocol
WebDriver BiDi
Tracking
(Not tracked)
RESOLVED
INCOMPLETE
People
(Reporter: intermittent-bug-filer, Unassigned)
References
(Depends on 1 open bug)
Details
(Keywords: intermittent-failure)
Filed by: nfay [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=468268139&repo=mozilla-beta
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/HjbkSg60RoyPtdCCxy2IBg/runs/0/artifacts/public/logs/live_backing.log
[task 2024-07-28T10:02:09.603Z] 10:02:09 INFO - TEST-PASS | /webdriver/tests/bidi/network/fetch_error/fetch_error.py | test_request_method[OPTIONS-True]
[task 2024-07-28T10:02:09.603Z] 10:02:09 INFO - TEST-PASS | /webdriver/tests/bidi/network/fetch_error/fetch_error.py | test_request_method[DELETE-True]
[task 2024-07-28T10:02:09.603Z] 10:02:09 INFO - TEST-UNEXPECTED-FAIL | /webdriver/tests/bidi/network/fetch_error/fetch_error.py | test_request_method[PATCH-True] - webdriver.error.TimeoutException: timeout (500): Timed out after 2.1 seconds
[task 2024-07-28T10:02:09.603Z] 10:02:09 INFO - bidi_session = <webdriver.bidi.client.BidiSession object at 0x000001A2A346CE50>
[task 2024-07-28T10:02:09.604Z] 10:02:09 INFO - wait_for_event = <function wait_for_event.<locals>.wait_for_event at 0x000001A2A381B9C0>
[task 2024-07-28T10:02:09.604Z] 10:02:09 INFO - wait_for_future_safe = <function wait_for_future_safe.<locals>.wait_for_future_safe at 0x000001A2A392D9E0>
[task 2024-07-28T10:02:09.604Z] 10:02:09 INFO - fetch = <function fetch.<locals>.fetch at 0x000001A2A392CC20>
[task 2024-07-28T10:02:09.604Z] 10:02:09 INFO - setup_network_test = <function setup_network_test.<locals>._setup_network_test at 0x000001A2A392D260>
[task 2024-07-28T10:02:09.604Z] 10:02:09 INFO - method = 'PATCH', has_preflight = True
[task 2024-07-28T10:02:09.604Z] 10:02:09 INFO -
[task 2024-07-28T10:02:09.604Z] 10:02:09 INFO - @pytest.mark.parametrize(
[task 2024-07-28T10:02:09.605Z] 10:02:09 INFO - "method, has_preflight",
[task 2024-07-28T10:02:09.605Z] 10:02:09 INFO - [
[task 2024-07-28T10:02:09.605Z] 10:02:09 INFO - ("GET", False),
[task 2024-07-28T10:02:09.605Z] 10:02:09 INFO - ("HEAD", False),
[task 2024-07-28T10:02:09.605Z] 10:02:09 INFO - ("POST", False),
[task 2024-07-28T10:02:09.605Z] 10:02:09 INFO - ("OPTIONS", True),
[task 2024-07-28T10:02:09.605Z] 10:02:09 INFO - ("DELETE", True),
[task 2024-07-28T10:02:09.605Z] 10:02:09 INFO - ("PATCH", True),
[task 2024-07-28T10:02:09.605Z] 10:02:09 INFO - ("PUT", True),
[task 2024-07-28T10:02:09.605Z] 10:02:09 INFO - ],
[task 2024-07-28T10:02:09.605Z] 10:02:09 INFO - )
[task 2024-07-28T10:02:09.605Z] 10:02:09 INFO - @pytest.mark.asyncio
[task 2024-07-28T10:02:09.605Z] 10:02:09 INFO - async def test_request_method(
[task 2024-07-28T10:02:09.605Z] 10:02:09 INFO - bidi_session,
[task 2024-07-28T10:02:09.605Z] 10:02:09 INFO - wait_for_event,
[task 2024-07-28T10:02:09.605Z] 10:02:09 INFO - wait_for_future_safe,
[task 2024-07-28T10:02:09.605Z] 10:02:09 INFO - fetch,
[task 2024-07-28T10:02:09.606Z] 10:02:09 INFO - setup_network_test,
[task 2024-07-28T10:02:09.606Z] 10:02:09 INFO - method,
[task 2024-07-28T10:02:09.606Z] 10:02:09 INFO - has_preflight,
[task 2024-07-28T10:02:09.606Z] 10:02:09 INFO - ):
[task 2024-07-28T10:02:09.606Z] 10:02:09 INFO - network_events = await setup_network_test(events=[FETCH_ERROR_EVENT])
[task 2024-07-28T10:02:09.606Z] 10:02:09 INFO - events = network_events[FETCH_ERROR_EVENT]
[task 2024-07-28T10:02:09.606Z] 10:02:09 INFO -
[task 2024-07-28T10:02:09.606Z] 10:02:09 INFO - asyncio.ensure_future(fetch(PAGE_INVALID_URL, method=method))
[task 2024-07-28T10:02:09.606Z] 10:02:09 INFO -
[task 2024-07-28T10:02:09.606Z] 10:02:09 INFO - # Requests which might update the server will also fail the CORS preflight
[task 2024-07-28T10:02:09.606Z] 10:02:09 INFO - # request which uses the OPTIONS method.
[task 2024-07-28T10:02:09.606Z] 10:02:09 INFO - expected_events = 2 if has_preflight else 1
[task 2024-07-28T10:02:09.606Z] 10:02:09 INFO -
[task 2024-07-28T10:02:09.606Z] 10:02:09 INFO - wait = AsyncPoll(bidi_session, timeout=2)
[task 2024-07-28T10:02:09.606Z] 10:02:09 INFO - > await wait.until(lambda _: len(events) >= expected_events)
[task 2024-07-28T10:02:09.606Z] 10:02:09 INFO -
[task 2024-07-28T10:02:09.606Z] 10:02:09 INFO - bidi_session = <webdriver.bidi.client.BidiSession object at 0x000001A2A346CE50>
[task 2024-07-28T10:02:09.607Z] 10:02:09 INFO - events = []
[task 2024-07-28T10:02:09.607Z] 10:02:09 INFO - expected_events = 2
[task 2024-07-28T10:02:09.607Z] 10:02:09 INFO - fetch = <function fetch.<locals>.fetch at 0x000001A2A392CC20>
[task 2024-07-28T10:02:09.607Z] 10:02:09 INFO - has_preflight = True
[task 2024-07-28T10:02:09.607Z] 10:02:09 INFO - method = 'PATCH'
[task 2024-07-28T10:02:09.607Z] 10:02:09 INFO - network_events = {'network.fetchError': []}
[task 2024-07-28T10:02:09.607Z] 10:02:09 INFO - setup_network_test = <function setup_network_test.<locals>._setup_network_test at 0x000001A2A392D260>
[task 2024-07-28T10:02:09.607Z] 10:02:09 INFO - wait = <tests.support.sync.AsyncPoll object at 0x000001A2A396EB50>
[task 2024-07-28T10:02:09.607Z] 10:02:09 INFO - wait_for_event = <function wait_for_event.<locals>.wait_for_event at 0x000001A2A381B9C0>
[task 2024-07-28T10:02:09.607Z] 10:02:09 INFO - wait_for_future_safe = <function wait_for_future_safe.<locals>.wait_for_future_safe at 0x000001A2A392D9E0>
[task 2024-07-28T10:02:09.607Z] 10:02:09 INFO -
[task 2024-07-28T10:02:09.607Z] 10:02:09 INFO - tests\web-platform\tests\webdriver\tests\bidi\network\fetch_error\fetch_error.py:189:
[task 2024-07-28T10:02:09.607Z] 10:02:09 INFO - _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
[task 2024-07-28T10:02:09.607Z] 10:02:09 INFO - tests\web-platform\tests\webdriver\tests\support\sync.py:279: in until
[task 2024-07-28T10:02:09.607Z] 10:02:09 INFO - return await poll()
[task 2024-07-28T10:02:09.607Z] 10:02:09 INFO - condition = <function test_request_method.<locals>.<lambda> at 0x000001A2A392C180>
[task 2024-07-28T10:02:09.607Z] 10:02:09 INFO - poll = <function AsyncPoll.until.<locals>.poll at 0x000001A2A392CAE0>
[task 2024-07-28T10:02:09.608Z] 10:02:09 INFO - self = <tests.support.sync.AsyncPoll object at 0x000001A2A396EB50>
[task 2024-07-28T10:02:09.608Z] 10:02:09 INFO - _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
[task 2024-07-28T10:02:09.608Z] 10:02:09 INFO -
[task 2024-07-28T10:02:09.608Z] 10:02:09 INFO - async def poll():
[task 2024-07-28T10:02:09.608Z] 10:02:09 INFO - result = None
[task 2024-07-28T10:02:09.608Z] 10:02:09 INFO - traceback = None
[task 2024-07-28T10:02:09.608Z] 10:02:09 INFO - start = self.clock.time()
[task 2024-07-28T10:02:09.608Z] 10:02:09 INFO - end = start + self.timeout
[task 2024-07-28T10:02:09.608Z] 10:02:09 INFO -
[task 2024-07-28T10:02:09.608Z] 10:02:09 INFO - while not self.clock.time() >= end:
[task 2024-07-28T10:02:09.608Z] 10:02:09 INFO - next = self.clock.time() + self.interval
[task 2024-07-28T10:02:09.608Z] 10:02:09 INFO -
[task 2024-07-28T10:02:09.608Z] 10:02:09 INFO - try:
[task 2024-07-28T10:02:09.608Z] 10:02:09 INFO - result = condition(self.session)
[task 2024-07-28T10:02:09.608Z] 10:02:09 INFO - if inspect.isawaitable(result):
[task 2024-07-28T10:02:09.608Z] 10:02:09 INFO - result = await result
[task 2024-07-28T10:02:09.608Z] 10:02:09 INFO - except (KeyboardInterrupt, SystemExit):
[task 2024-07-28T10:02:09.609Z] 10:02:09 INFO - raise
[task 2024-07-28T10:02:09.609Z] 10:02:09 INFO - except self.exceptions:
[task 2024-07-28T10:02:09.609Z] 10:02:09 INFO - _, _, traceback = sys.exc_info()
[task 2024-07-28T10:02:09.609Z] 10:02:09 INFO -
[task 2024-07-28T10:02:09.609Z] 10:02:09 INFO - # re-adjust the interval depending on how long
[task 2024-07-28T10:02:09.609Z] 10:02:09 INFO - # the callback took to evaluate the condition
[task 2024-07-28T10:02:09.609Z] 10:02:09 INFO - interval_new = max(next - self.clock.time(), 0)
[task 2024-07-28T10:02:09.609Z] 10:02:09 INFO -
[task 2024-07-28T10:02:09.609Z] 10:02:09 INFO - if result:
[task 2024-07-28T10:02:09.609Z] 10:02:09 INFO - return result
[task 2024-07-28T10:02:09.609Z] 10:02:09 INFO -
[task 2024-07-28T10:02:09.609Z] 10:02:09 INFO - await asyncio.sleep(interval_new)
[task 2024-07-28T10:02:09.609Z] 10:02:09 INFO -
[task 2024-07-28T10:02:09.609Z] 10:02:09 INFO - if self.exc_cls is not None:
[task 2024-07-28T10:02:09.609Z] 10:02:09 INFO - elapsed = round((self.clock.time() - start), 1)
[task 2024-07-28T10:02:09.609Z] 10:02:09 INFO - message = f"Timed out after {elapsed} seconds"
[task 2024-07-28T10:02:09.609Z] 10:02:09 INFO - if self.exc_msg is not None:
[task 2024-07-28T10:02:09.609Z] 10:02:09 INFO - message = f"{message} with message: {self.exc_msg}"
[task 2024-07-28T10:02:09.609Z] 10:02:09 INFO - > raise self.exc_cls(message=message).with_traceback(traceback)
[task 2024-07-28T10:02:09.609Z] 10:02:09 INFO - E webdriver.error.TimeoutException: timeout (500): Timed out after 2.1 seconds
[task 2024-07-28T10:02:09.609Z] 10:02:09 INFO -
[task 2024-07-28T10:02:09.610Z] 10:02:09 INFO - condition = <function test_request_method.<locals>.<lambda> at 0x000001A2A392C180>
[task 2024-07-28T10:02:09.610Z] 10:02:09 INFO - elapsed = 2.1
[task 2024-07-28T10:02:09.610Z] 10:02:09 INFO - end = 610.25
[task 2024-07-28T10:02:09.610Z] 10:02:09 INFO - interval_new = 0.10000000000002274
[task 2024-07-28T10:02:09.610Z] 10:02:09 INFO - message = 'Timed out after 2.1 seconds'
[task 2024-07-28T10:02:09.610Z] 10:02:09 INFO - next = 610.3340000000001
[task 2024-07-28T10:02:09.610Z] 10:02:09 INFO - result = False
[task 2024-07-28T10:02:09.610Z] 10:02:09 INFO - self = <tests.support.sync.AsyncPoll object at 0x000001A2A396EB50>
[task 2024-07-28T10:02:09.610Z] 10:02:09 INFO - start = 608.25
[task 2024-07-28T10:02:09.610Z] 10:02:09 INFO - traceback = None
[task 2024-07-28T10:02:09.610Z] 10:02:09 INFO -
[task 2024-07-28T10:02:09.610Z] 10:02:09 INFO - tests\web-platform\tests\webdriver\tests\support\sync.py:275: TimeoutException
[task 2024-07-28T10:02:09.619Z] 10:02:09 INFO - ...
[task 2024-07-28T10:02:09.619Z] 10:02:09 INFO - TEST-OK | /webdriver/tests/bidi/network/fetch_error/fetch_error.py | took 17166ms
| Comment hidden (Intermittent Failures Robot) |
|
||
Comment 2•3 months ago
|
||
Lets not make that a generic bug for now given it happened only once. Also without trace logs (bug 1906355) it's hard to guess what went wrong.
Depends on: 1906355
Summary: Intermittent Wd | webdriver.error.TimeoutException: timeout (500): Timed out after xx seconds → Intermittent /webdriver/tests/bidi/network/fetch_error/fetch_error.py | test_request_method[PATCH-True] - webdriver.error.TimeoutException: timeout (500): Timed out after 2.1 seconds
|
||
Comment 3•3 months ago
|
||
There's a second incident of this failure here , would it be alright to convert it back?
Flags: needinfo?(hskupin)
|
|
||
Comment 4•2 months ago
|
||
Those are different issues and I think it would be good to keep them in separate bugs. Julian, do you agree?
Flags: needinfo?(hskupin) → needinfo?(jdescottes)
|
||
Comment 5•2 months ago
|
||
I agree let's keep them separated. The other one seems to hang while waiting on an intercepted auth request.
Flags: needinfo?(jdescottes)
|
|
||
Comment 6•2 months ago
|
||
Norisz can you please make sure to update the classification and get the new intermittent failure bug created? Thanks.
Flags: needinfo?(nfay)
|
||
Comment 8•1 month ago
|
||
https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit BugBot documentation.
Status: NEW → RESOLVED
Closed: 1 month ago
Resolution: --- → INCOMPLETE
You need to log in
before you can comment on or make changes to this bug.
Description
•