1841569 - Intermittent WD TEST-UNEXPECTED-FAIL <random WD> | test_iframe - webdriver.error.TimeoutException: timeout (500): Timed out after 5.0 seconds with message: Didn't receive dom content loaded events for frames / context load events for frames

Status: RESOLVED INCOMPLETE

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

Description

[Treeherder Bug Filer]

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

---

[task 2023-07-04T01:18:09.635Z] 01:18:09     INFO - TEST-PASS | /webdriver/tests/bidi/browsing_context/dom_content_loaded/dom_content_loaded.py | test_timestamp 
[task 2023-07-04T01:18:09.635Z] 01:18:09     INFO - TEST-UNEXPECTED-FAIL | /webdriver/tests/bidi/browsing_context/dom_content_loaded/dom_content_loaded.py | test_iframe - webdriver.error.TimeoutException: timeout (500): Timed out after 5.0 seconds with message: Didn't receive dom content loaded events for frames
[task 2023-07-04T01:18:09.635Z] 01:18:09     INFO - bidi_session = <webdriver.bidi.client.BidiSession object at 0x00000194046BBBB0>
[task 2023-07-04T01:18:09.635Z] 01:18:09     INFO - subscribe_events = <function subscribe_events.<locals>.subscribe_events at 0x00000194046F0B80>
[task 2023-07-04T01:18:09.635Z] 01:18:09     INFO - new_tab = {'context': '77b35bcd-6d24-44e8-a233-9ee848c0b612'}
[task 2023-07-04T01:18:09.635Z] 01:18:09     INFO - test_page = 'http://web-platform.test:8000/webdriver/tests/support/inline.py?doc=%3C%21doctype+html%3E%0A%3Cmeta+charset%3DUTF-8%3E%0A%3Cdiv%3Efoo%3C%2Fdiv%3E&mime=text%2Fhtml&charset=UTF-8'
[task 2023-07-04T01:18:09.635Z] 01:18:09     INFO - test_page_same_origin_frame = 'http://web-platform.test:8000/webdriver/tests/support/inline.py?doc=%3C%21doctype+html%3E%0A%3Cmeta+charset%3DUTF-8%3...253Efoo%253C%252Fdiv%253E%26mime%3Dtext%252Fhtml%26charset%3DUTF-8%27%3E%3C%2Fiframe%3E&mime=text%2Fhtml&charset=UTF-8'
[task 2023-07-04T01:18:09.635Z] 01:18:09     INFO - 
[task 2023-07-04T01:18:09.635Z] 01:18:09     INFO -     async def test_iframe(bidi_session, subscribe_events, new_tab, test_page, test_page_same_origin_frame):
[task 2023-07-04T01:18:09.635Z] 01:18:09     INFO -         events = []
[task 2023-07-04T01:18:09.636Z] 01:18:09     INFO -     
[task 2023-07-04T01:18:09.636Z] 01:18:09     INFO -         async def on_event(method, data):
[task 2023-07-04T01:18:09.636Z] 01:18:09     INFO -             # Filter out events for about:blank to avoid browser differences
[task 2023-07-04T01:18:09.636Z] 01:18:09     INFO -             if data["url"] != 'about:blank':
[task 2023-07-04T01:18:09.636Z] 01:18:09     INFO -                 events.append(data)
[task 2023-07-04T01:18:09.636Z] 01:18:09     INFO -     
[task 2023-07-04T01:18:09.636Z] 01:18:09     INFO -         remove_listener = bidi_session.add_event_listener(
[task 2023-07-04T01:18:09.636Z] 01:18:09     INFO -             DOM_CONTENT_LOADED_EVENT, on_event
[task 2023-07-04T01:18:09.636Z] 01:18:09     INFO -         )
[task 2023-07-04T01:18:09.636Z] 01:18:09     INFO -         await subscribe_events(events=[DOM_CONTENT_LOADED_EVENT])
[task 2023-07-04T01:18:09.636Z] 01:18:09     INFO -     
[task 2023-07-04T01:18:09.636Z] 01:18:09     INFO -         await bidi_session.browsing_context.navigate(
[task 2023-07-04T01:18:09.636Z] 01:18:09     INFO -             context=new_tab["context"], url=test_page_same_origin_frame
[task 2023-07-04T01:18:09.636Z] 01:18:09     INFO -         )
[task 2023-07-04T01:18:09.636Z] 01:18:09     INFO -     
[task 2023-07-04T01:18:09.636Z] 01:18:09     INFO -         wait = AsyncPoll(
[task 2023-07-04T01:18:09.636Z] 01:18:09     INFO -             bidi_session, message="Didn't receive dom content loaded events for frames"
[task 2023-07-04T01:18:09.636Z] 01:18:09     INFO -         )
[task 2023-07-04T01:18:09.636Z] 01:18:09     INFO - >       await wait.until(lambda _: len(events) >= 2)
[task 2023-07-04T01:18:09.636Z] 01:18:09     INFO - 
[task 2023-07-04T01:18:09.636Z] 01:18:09     INFO - bidi_session = <webdriver.bidi.client.BidiSession object at 0x00000194046BBBB0>
[task 2023-07-04T01:18:09.636Z] 01:18:09     INFO - events     = []
[task 2023-07-04T01:18:09.636Z] 01:18:09     INFO - new_tab    = {'context': '77b35bcd-6d24-44e8-a233-9ee848c0b612'}
[task 2023-07-04T01:18:09.636Z] 01:18:09     INFO - on_event   = <function test_iframe.<locals>.on_event at 0x000001940473D550>
[task 2023-07-04T01:18:09.637Z] 01:18:09     INFO - remove_listener = <function BidiSession.add_event_listener.<locals>.<lambda> at 0x000001940473D4C0>
[task 2023-07-04T01:18:09.637Z] 01:18:09     INFO - subscribe_events = <function subscribe_events.<locals>.subscribe_events at 0x00000194046F0B80>
[task 2023-07-04T01:18:09.637Z] 01:18:09     INFO - test_page  = 'http://web-platform.test:8000/webdriver/tests/support/inline.py?doc=%3C%21doctype+html%3E%0A%3Cmeta+charset%3DUTF-8%3E%0A%3Cdiv%3Efoo%3C%2Fdiv%3E&mime=text%2Fhtml&charset=UTF-8'
[task 2023-07-04T01:18:09.637Z] 01:18:09     INFO - test_page_same_origin_frame = 'http://web-platform.test:8000/webdriver/tests/support/inline.py?doc=%3C%21doctype+html%3E%0A%3Cmeta+charset%3DUTF-8%3E%0A%3Ciframe+src%3D%27http%3A%2F%2Fweb-platform.test%3A8000%2Fwebdriver%2Ftests%2Fsupport%2Finline.py%3Fdoc%3D%253C%2521doctype%2Bhtml%253E%250A%253Cmeta%2Bcharset%253DUTF-8%253E%250A%253Cdiv%253Efoo%253C%252Fdiv%253E%26mime%3Dtext%252Fhtml%26charset%3DUTF-8%27%3E%3C%2Fiframe%3E&mime=text%2Fhtml&charset=UTF-8'
[task 2023-07-04T01:18:09.637Z] 01:18:09     INFO - wait       = <tests.support.sync.AsyncPoll object at 0x000001940473F1F0>
[task 2023-07-04T01:18:09.637Z] 01:18:09     INFO - 
[task 2023-07-04T01:18:09.637Z] 01:18:09     INFO - tests\web-platform\tests\webdriver\tests\bidi\browsing_context\dom_content_loaded\dom_content_loaded.py:89: 
[task 2023-07-04T01:18:09.637Z] 01:18:09     INFO - _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
[task 2023-07-04T01:18:09.637Z] 01:18:09     INFO - tests\web-platform\tests\webdriver\tests\support\sync.py:276: in until
[task 2023-07-04T01:18:09.637Z] 01:18:09     INFO -     return await poll()
[task 2023-07-04T01:18:09.637Z] 01:18:09     INFO -         condition  = <function test_iframe.<locals>.<lambda> at 0x000001940473DAF0>
[task 2023-07-04T01:18:09.637Z] 01:18:09     INFO -         poll       = <function AsyncPoll.until.<locals>.poll at 0x000001940473DB80>
[task 2023-07-04T01:18:09.637Z] 01:18:09     INFO -         self       = <tests.support.sync.AsyncPoll object at 0x000001940473F1F0>
[task 2023-07-04T01:18:09.637Z] 01:18:09     INFO - _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
[task 2023-07-04T01:18:09.637Z] 01:18:09     INFO - 
[task 2023-07-04T01:18:09.637Z] 01:18:09     INFO -     async def poll():
[task 2023-07-04T01:18:09.637Z] 01:18:09     INFO -         result = None
[task 2023-07-04T01:18:09.637Z] 01:18:09     INFO -         traceback = None
[task 2023-07-04T01:18:09.637Z] 01:18:09     INFO -         start = self.clock.time()
[task 2023-07-04T01:18:09.637Z] 01:18:09     INFO -         end = start + self.timeout
[task 2023-07-04T01:18:09.637Z] 01:18:09     INFO -     
[task 2023-07-04T01:18:09.637Z] 01:18:09     INFO -         while not self.clock.time() >= end:
[task 2023-07-04T01:18:09.637Z] 01:18:09     INFO -             next = self.clock.time() + self.interval
[task 2023-07-04T01:18:09.637Z] 01:18:09     INFO -     
[task 2023-07-04T01:18:09.638Z] 01:18:09     INFO -             try:
[task 2023-07-04T01:18:09.638Z] 01:18:09     INFO -                 result = condition(self.session)
[task 2023-07-04T01:18:09.638Z] 01:18:09     INFO -             except (KeyboardInterrupt, SystemExit):
[task 2023-07-04T01:18:09.638Z] 01:18:09     INFO -                 raise
[task 2023-07-04T01:18:09.638Z] 01:18:09     INFO -             except self.exceptions:
[task 2023-07-04T01:18:09.638Z] 01:18:09     INFO -                 _, _, traceback = sys.exc_info()
[task 2023-07-04T01:18:09.638Z] 01:18:09     INFO -     
[task 2023-07-04T01:18:09.638Z] 01:18:09     INFO -             # re-adjust the interval depending on how long
[task 2023-07-04T01:18:09.638Z] 01:18:09     INFO -             # the callback took to evaluate the condition
[task 2023-07-04T01:18:09.638Z] 01:18:09     INFO -             interval_new = max(next - self.clock.time(), 0)
[task 2023-07-04T01:18:09.638Z] 01:18:09     INFO -     
[task 2023-07-04T01:18:09.638Z] 01:18:09     INFO -             if result:
[task 2023-07-04T01:18:09.638Z] 01:18:09     INFO -                 return result
[task 2023-07-04T01:18:09.638Z] 01:18:09     INFO -     
[task 2023-07-04T01:18:09.638Z] 01:18:09     INFO -             await asyncio.sleep(interval_new)
[task 2023-07-04T01:18:09.638Z] 01:18:09     INFO -     
[task 2023-07-04T01:18:09.638Z] 01:18:09     INFO -         if self.exc_cls is not None:
[task 2023-07-04T01:18:09.638Z] 01:18:09     INFO -             elapsed = round((self.clock.time() - start), 1)
[task 2023-07-04T01:18:09.638Z] 01:18:09     INFO -             message = f"Timed out after {elapsed} seconds"
[task 2023-07-04T01:18:09.638Z] 01:18:09     INFO -             if self.exc_msg is not None:
[task 2023-07-04T01:18:09.638Z] 01:18:09     INFO -                 message = f"{message} with message: {self.exc_msg}"
[task 2023-07-04T01:18:09.638Z] 01:18:09     INFO - >           raise self.exc_cls(message=message).with_traceback(traceback)
[task 2023-07-04T01:18:09.638Z] 01:18:09     INFO - E           webdriver.error.TimeoutException: timeout (500): Timed out after 5.0 seconds with message: Didn't receive dom content loaded events for frames
[task 2023-07-04T01:18:09.638Z] 01:18:09     INFO - 
[task 2023-07-04T01:18:09.638Z] 01:18:09     INFO - condition  = <function test_iframe.<locals>.<lambda> at 0x000001940473DAF0>
[task 2023-07-04T01:18:09.639Z] 01:18:09     INFO - elapsed    = 5.0
[task 2023-07-04T01:18:09.639Z] 01:18:09     INFO - end        = 639.171
[task 2023-07-04T01:18:09.639Z] 01:18:09     INFO - interval_new = 0.10000000000002274
[task 2023-07-04T01:18:09.639Z] 01:18:09     INFO - message    = ("Timed out after 5.0 seconds with message: Didn't receive dom content loaded "
[task 2023-07-04T01:18:09.639Z] 01:18:09     INFO -  'events for frames')
[task 2023-07-04T01:18:09.639Z] 01:18:09     INFO - next       = 639.2090000000001
[task 2023-07-04T01:18:09.639Z] 01:18:09     INFO - result     = False
[task 2023-07-04T01:18:09.639Z] 01:18:09     INFO - self       = <tests.support.sync.AsyncPoll object at 0x000001940473F1F0>
[task 2023-07-04T01:18:09.639Z] 01:18:09     INFO - start      = 634.171
[task 2023-07-04T01:18:09.639Z] 01:18:09     INFO - traceback  = None
[task 2023-07-04T01:18:09.639Z] 01:18:09     INFO - 
[task 2023-07-04T01:18:09.639Z] 01:18:09     INFO - tests\web-platform\tests\webdriver\tests\support\sync.py:272: TimeoutException
[task 2023-07-04T01:18:09.641Z] 01:18:09     INFO - ....
[task 2023-07-04T01:18:09.641Z] 01:18:09     INFO - TEST-OK | /webdriver/tests/bidi/browsing_context/dom_content_loaded/dom_content_loaded.py | took 12690ms

Comment 1

[Intermittent Failures Robot]

1 failures in 2956 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 1

Platform and build breakdown:

• windows11-64-2009-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1841569&startday=2023-07-03&endday=2023-07-09&tree=all

Comment 2

[Intermittent Failures Robot]

1 failures in 3309 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-beta: 1

Platform and build breakdown:

• windows11-64-2009-qr: 1
  • debug: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1841569&startday=2023-07-10&endday=2023-07-16&tree=all

Comment 3

[Henrik Skupin [:whimboo][⌚️UTC+1] (away from Feb 12th - Feb 22nd)]

Single failure only and no more occurrences within the last month.

Comment 4

[Treeherder Bug Filer]

New failure instance: https://treeherder.mozilla.org/logviewer?job_id=455140421&repo=mozilla-central

Comment 5

[Intermittent Failures Robot]

1 failures in 4252 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 1

Platform and build breakdown:

• windows11-64-2009-shippable-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1841569&startday=2024-04-15&endday=2024-04-21&tree=all

Comment 6

[Intermittent Failures Robot]

1 failures in 4336 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 1

Platform and build breakdown:

• windows11-32-2009-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1841569&startday=2024-04-22&endday=2024-04-28&tree=all

Comment 7

[BugBot [:suhaib / :marco/ :calixte]]

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit BugBot documentation.

Comment 8

[Treeherder Bug Filer]

New failure instance: https://treeherder.mozilla.org/logviewer?job_id=472868471&repo=mozilla-central

Comment 9

[Intermittent Failures Robot]

1 failures in 3668 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 1

Platform and build breakdown:

• windows11-32-2009-shippable-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1841569&startday=2024-09-02&endday=2024-09-08&tree=all

Comment 10

[BugBot [:suhaib / :marco/ :calixte]]

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit BugBot documentation.

Comment 11

[Treeherder Bug Filer]

New failure instance: https://treeherder.mozilla.org/logviewer?job_id=484832445&repo=try

Comment 12

[Intermittent Failures Robot]

1 failures in 3953 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• try: 1

Platform and build breakdown:

• windows11-32-2009-qr: 1
  • debug: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1841569&startday=2024-11-25&endday=2024-12-01&tree=all

Comment 13

[Intermittent Failures Robot]

Summary

2 failures in 4615 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 2

Platform and build breakdown:

• android-em-7-0-x86_64-lite-qr: 2
  • opt: 2

Table

	1proc	a11y-checks-swr	condprof	fis	fis-hv	fis-hv-s	fis-s	headless-s	http2	http3	no_variant	nofis	nofis-aab	nofis-s	nofis-ship	nofis-ship-s	nofis-spi	nofis-swr	nofis-swr-s	nogpu	nogpu-s	s	spi	spi-nw	spi-nw-1proc	spi-nw-s	swr	wr-dc1-p	xorig	xorig-s
android-em-7-0-x86_64-lite-qr/opt											1	1

For more details, see:

https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1841569&startday=2024-12-09&endday=2024-12-15&tree=all

Comment 14

[BugBot [:suhaib / :marco/ :calixte]]

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit BugBot documentation.