Open Bug 1858034 Opened 1 year ago Updated 5 days ago

Intermittent /webdriver/tests/bidi/browsing_context/navigation_started/navigation_started.py | single tracking bug

Categories

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

defect

Tracking

(Not tracked)

REOPENED

People

(Reporter: intermittent-bug-filer, Unassigned)

References

(Depends on 3 open bugs)

Details

(Keywords: intermittent-failure)

Attachments

(1 obsolete file)

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


[task 2023-10-09T23:58:44.241Z] 23:58:44     INFO - PID 1317 | 1696895924240	Marionette	DEBUG	Closed connection 0
[task 2023-10-09T23:58:44.254Z] 23:58:44     INFO - PID 1317 | console.error: ({})
[task 2023-10-09T23:58:44.403Z] 23:58:44     INFO - PID 1317 | 1696895924401	geckodriver::browser	DEBUG	Browser process stopped: exit status: 0
[task 2023-10-09T23:58:44.403Z] 23:58:44     INFO - PID 1317 | 1696895924402	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2023-10-09T23:58:44.407Z] 23:58:44     INFO - STDOUT: =================================== FAILURES ===================================
[task 2023-10-09T23:58:44.408Z] 23:58:44     INFO - STDOUT: _____________________________ test_nested_iframes ______________________________
[task 2023-10-09T23:58:44.409Z] 23:58:44     INFO - STDOUT: bidi_session = <webdriver.bidi.client.BidiSession object at 0x7f94b8f1c690>
[task 2023-10-09T23:58:44.409Z] 23:58:44     INFO - STDOUT: subscribe_events = <function subscribe_events.<locals>.subscribe_events at 0x7f94b8efdc20>
[task 2023-10-09T23:58:44.411Z] 23:58:44     INFO - STDOUT: top_context = {'children': [{'children': [], 'context': '17179869185', 'url': 'https://web-platform.test:8443/webdriver/tests/suppor...53Efoo%253C%252Fdiv%253E%26mime%3Dtext%252Fhtml%26charset%3DUTF-8%27%3E%3C%2Fiframe%3E&mime=text%2Fhtml&charset=UTF-8'}
[task 2023-10-09T23:58:44.412Z] 23:58:44     INFO - STDOUT: test_page_nested_frames = 'https://web-platform.test:8443/webdriver/tests/support/inline.py?doc=%3C%21doctype+html%3E%0A%3Cmeta+charset%3DUTF-8%...253E%253C%252Fiframe%253E%26mime%3Dtext%252Fhtml%26charset%3DUTF-8%27%3E%3C%2Fiframe%3E&mime=text%2Fhtml&charset=UTF-8'
[task 2023-10-09T23:58:44.412Z] 23:58:44     INFO - STDOUT: test_page_same_origin_frame = 'https://web-platform.test:8443/webdriver/tests/support/inline.py?doc=%3C%21doctype+html%3E%0A%3Cmeta+charset%3DUTF-8%...253Efoo%253C%252Fdiv%253E%26mime%3Dtext%252Fhtml%26charset%3DUTF-8%27%3E%3C%2Fiframe%3E&mime=text%2Fhtml&charset=UTF-8'
[task 2023-10-09T23:58:44.413Z] 23:58:44     INFO - STDOUT: test_page = 'https://web-platform.test:8443/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-10-09T23:58:44.414Z] 23:58:44     INFO - STDOUT:     async def test_nested_iframes(
[task 2023-10-09T23:58:44.415Z] 23:58:44     INFO - STDOUT:         bidi_session,
[task 2023-10-09T23:58:44.415Z] 23:58:44     INFO - STDOUT:         subscribe_events,
[task 2023-10-09T23:58:44.416Z] 23:58:44     INFO - STDOUT:         top_context,
[task 2023-10-09T23:58:44.417Z] 23:58:44     INFO - STDOUT:         test_page_nested_frames,
[task 2023-10-09T23:58:44.417Z] 23:58:44     INFO - STDOUT:         test_page_same_origin_frame,
[task 2023-10-09T23:58:44.418Z] 23:58:44     INFO - STDOUT:         test_page,
[task 2023-10-09T23:58:44.419Z] 23:58:44     INFO - STDOUT:     ):
[task 2023-10-09T23:58:44.419Z] 23:58:44     INFO - STDOUT:         events = []
[task 2023-10-09T23:58:44.420Z] 23:58:44     INFO - STDOUT:     
[task 2023-10-09T23:58:44.421Z] 23:58:44     INFO - STDOUT:         async def on_event(method, data):
[task 2023-10-09T23:58:44.422Z] 23:58:44     INFO - STDOUT:             events.append(data)
[task 2023-10-09T23:58:44.422Z] 23:58:44     INFO - STDOUT:     
[task 2023-10-09T23:58:44.423Z] 23:58:44     INFO - STDOUT:         remove_listener = bidi_session.add_event_listener(
[task 2023-10-09T23:58:44.424Z] 23:58:44     INFO - STDOUT:             NAVIGATION_STARTED_EVENT, on_event
[task 2023-10-09T23:58:44.424Z] 23:58:44     INFO - STDOUT:         )
[task 2023-10-09T23:58:44.425Z] 23:58:44     INFO - STDOUT:     
[task 2023-10-09T23:58:44.426Z] 23:58:44     INFO - STDOUT:         await subscribe_events(events=[NAVIGATION_STARTED_EVENT])
[task 2023-10-09T23:58:44.426Z] 23:58:44     INFO - STDOUT:     
[task 2023-10-09T23:58:44.427Z] 23:58:44     INFO - STDOUT:         result = await bidi_session.browsing_context.navigate(
[task 2023-10-09T23:58:44.428Z] 23:58:44     INFO - STDOUT:             context=top_context["context"], url=test_page_nested_frames, wait="complete"
[task 2023-10-09T23:58:44.428Z] 23:58:44     INFO - STDOUT:         )
[task 2023-10-09T23:58:44.429Z] 23:58:44     INFO - STDOUT:     
[task 2023-10-09T23:58:44.430Z] 23:58:44     INFO - STDOUT:         # Check that 3 navigation-started events were received, one for the top context
[task 2023-10-09T23:58:44.430Z] 23:58:44     INFO - STDOUT:         # and one for each of the 2 iframes.
[task 2023-10-09T23:58:44.431Z] 23:58:44     INFO - STDOUT: >       assert len(events) == 3
[task 2023-10-09T23:58:44.432Z] 23:58:44     INFO - STDOUT: E       assert 2 == 3
[task 2023-10-09T23:58:44.432Z] 23:58:44     INFO - STDOUT: E         +2
[task 2023-10-09T23:58:44.433Z] 23:58:44     INFO - STDOUT: E         -3
[task 2023-10-09T23:58:44.434Z] 23:58:44     INFO - STDOUT: bidi_session = <webdriver.bidi.client.BidiSession object at 0x7f94b8f1c690>
[task 2023-10-09T23:58:44.435Z] 23:58:44     INFO - STDOUT: events     = [{'context': '17179869186',
[task 2023-10-09T23:58:44.435Z] 23:58:44     INFO -   'navigation': '9a49048f-3eef-4648-8bc1-5f05fcc77a70',
[task 2023-10-09T23:58:44.436Z] 23:58:44     INFO -   'timestamp': 1696895922385,
[task 2023-10-09T23:58:44.436Z] 23:58:44     INFO -   'url': 'https://web-platform.test:8443/webdriver/tests/support/inline.py?doc=%3C%21doctype+html%3E%0A%3Cmeta+charset%3DUTF-8%3E%0A%3Ciframe+src%3D%27https%3A%2F%2Fweb-platform.test%3A8443%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-10-09T23:58:44.436Z] 23:58:44     INFO -  {'context': '17179869187',
[task 2023-10-09T23:58:44.436Z] 23:58:44     INFO -   'navigation': 'c6e6cf33-e23f-47af-9f6d-8ded778c1a85',
[task 2023-10-09T23:58:44.436Z] 23:58:44     INFO -   'timestamp': 1696895922396,
[task 2023-10-09T23:58:44.436Z] 23:58:44     INFO -   'url': 'https://web-platform.test:8443/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-10-09T23:58:44.437Z] 23:58:44     INFO - STDOUT: on_event   = <function test_nested_iframes.<locals>.on_event at 0x7f94b8efd830>
[task 2023-10-09T23:58:44.438Z] 23:58:44     INFO - STDOUT: remove_listener = <function BidiSession.add_event_listener.<locals>.<lambda> at 0x7f94b8ef1dd0>
[task 2023-10-09T23:58:44.439Z] 23:58:44     INFO - STDOUT: result     = {'navigation': 'f356cfdd-0252-4a2a-bca5-85caccff7d67',
[task 2023-10-09T23:58:44.439Z] 23:58:44     INFO -  'url': 'https://web-platform.test:8443/webdriver/tests/support/inline.py?doc=%3C%21doctype+html%3E%0A%3Cmeta+charset%3DUTF-8%3E%0A%3Ciframe+src%3D%27https%3A%2F%2Fweb-platform.test%3A8443%2Fwebdriver%2Ftests%2Fsupport%2Finline.py%3Fdoc%3D%253C%2521doctype%2Bhtml%253E%250A%253Cmeta%2Bcharset%253DUTF-8%253E%250A%253Ciframe%2Bsrc%253D%2527https%253A%252F%252Fweb-platform.test%253A8443%252Fwebdriver%252Ftests%252Fsupport%252Finline.py%253Fdoc%253D%25253C%252521doctype%252Bhtml%25253E%25250A%25253Cmeta%252Bcharset%25253DUTF-8%25253E%25250A%25253Cdiv%25253Efoo%25253C%25252Fdiv%25253E%2526mime%253Dtext%25252Fhtml%2526charset%253DUTF-8%2527%253E%253C%252Fiframe%253E%26mime%3Dtext%252Fhtml%26charset%3DUTF-8%27%3E%3C%2Fiframe%3E&mime=text%2Fhtml&charset=UTF-8'}
[task 2023-10-09T23:58:44.440Z] 23:58:44     INFO - STDOUT: subscribe_events = <function subscribe_events.<locals>.subscribe_events at 0x7f94b8efdc20>
[task 2023-10-09T23:58:44.441Z] 23:58:44     INFO - STDOUT: test_page  = 'https://web-platform.test:8443/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-10-09T23:58:44.443Z] 23:58:44     INFO - STDOUT: test_page_nested_frames = 'https://web-platform.test:8443/webdriver/tests/support/inline.py?doc=%3C%21doctype+html%3E%0A%3Cmeta+charset%3DUTF-8%3E%0A%3Ciframe+src%3D%27https%3A%2F%2Fweb-platform.test%3A8443%2Fwebdriver%2Ftests%2Fsupport%2Finline.py%3Fdoc%3D%253C%2521doctype%2Bhtml%253E%250A%253Cmeta%2Bcharset%253DUTF-8%253E%250A%253Ciframe%2Bsrc%253D%2527https%253A%252F%252Fweb-platform.test%253A8443%252Fwebdriver%252Ftests%252Fsupport%252Finline.py%253Fdoc%253D%25253C%252521doctype%252Bhtml%25253E%25250A%25253Cmeta%252Bcharset%25253DUTF-8%25253E%25250A%25253Cdiv%25253Efoo%25253C%25252Fdiv%25253E%2526mime%253Dtext%25252Fhtml%2526charset%253DUTF-8%2527%253E%253C%252Fiframe%253E%26mime%3Dtext%252Fhtml%26charset%3DUTF-8%27%3E%3C%2Fiframe%3E&mime=text%2Fhtml&charset=UTF-8'
[task 2023-10-09T23:58:44.444Z] 23:58:44     INFO - STDOUT: test_page_same_origin_frame = 'https://web-platform.test:8443/webdriver/tests/support/inline.py?doc=%3C%21doctype+html%3E%0A%3Cmeta+charset%3DUTF-8%3E%0A%3Ciframe+src%3D%27https%3A%2F%2Fweb-platform.test%3A8443%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-10-09T23:58:44.446Z] 23:58:44     INFO - STDOUT: top_context = {'children': [{'children': [],
[task 2023-10-09T23:58:44.446Z] 23:58:44     INFO -                'context': '17179869185',
[task 2023-10-09T23:58:44.446Z] 23:58:44     INFO -                'url': 'https://web-platform.test:8443/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-10-09T23:58:44.446Z] 23:58:44     INFO -  'context': 'a2724788-0911-4843-9386-a2f7a0208120',
[task 2023-10-09T23:58:44.446Z] 23:58:44     INFO -  'parent': None,
[task 2023-10-09T23:58:44.446Z] 23:58:44     INFO -  'url': 'https://web-platform.test:8443/webdriver/tests/support/inline.py?doc=%3C%21doctype+html%3E%0A%3Cmeta+charset%3DUTF-8%3E%0A%3Ciframe+src%3D%27https%3A%2F%2Fweb-platform.test%3A8443%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-10-09T23:58:44.447Z] 23:58:44     INFO - STDOUT: tests/web-platform/tests/webdriver/tests/bidi/browsing_context/navigation_started/navigation_started.py
[task 2023-10-09T23:58:44.448Z] 23:58:44     INFO - STDOUT: :168: AssertionError
[task 2023-10-09T23:58:44.448Z] 23:58:44     INFO - STDOUT: =========================== short test summary info ============================
[task 2023-10-09T23:58:44.449Z] 23:58:44     INFO - STDOUT: FAILED tests/web-platform/tests/webdriver/tests/bidi/browsing_context/navigation_started/navigation_started.py::test_nested_iframes
[task 2023-10-09T23:58:44.450Z] 23:58:44     INFO - STDOUT: ========================= 1 failed, 12 passed in 5.75s =========================
[task 2023-10-09T23:58:44.461Z] 23:58:44     INFO - 
[task 2023-10-09T23:58:44.461Z] 23:58:44     INFO - TEST-PASS | /webdriver/tests/bidi/browsing_context/navigation_started/navigation_started.py | test_unsubscribe 
[task 2023-10-09T23:58:44.461Z] 23:58:44     INFO - TEST-PASS | /webdriver/tests/bidi/browsing_context/navigation_started/navigation_started.py | test_subscribe 
[task 2023-10-09T23:58:44.461Z] 23:58:44     INFO - TEST-PASS | /webdriver/tests/bidi/browsing_context/navigation_started/navigation_started.py | test_timestamp 
[task 2023-10-09T23:58:44.461Z] 23:58:44     INFO - TEST-PASS | /webdriver/tests/bidi/browsing_context/navigation_started/navigation_started.py | test_iframe 
[task 2023-10-09T23:58:44.461Z] 23:58:44     INFO - TEST-UNEXPECTED-FAIL | /webdriver/tests/bidi/browsing_context/navigation_started/navigation_started.py | test_nested_iframes - assert 2 == 3
[task 2023-10-09T23:58:44.462Z] 23:58:44     INFO - bidi_session = <webdriver.bidi.client.BidiSession object at 0x7f94b8f1c690>
[task 2023-10-09T23:58:44.462Z] 23:58:44     INFO - subscribe_events = <function subscribe_events.<locals>.subscribe_events at 0x7f94b8efdc20>
[task 2023-10-09T23:58:44.462Z] 23:58:44     INFO - top_context = {'children': [{'children': [], 'context': '17179869185', 'url': 'https://web-platform.test:8443/webdriver/tests/suppor...53Efoo%253C%252Fdiv%253E%26mime%3Dtext%252Fhtml%26charset%3DUTF-8%27%3E%3C%2Fiframe%3E&mime=text%2Fhtml&charset=UTF-8'}
[task 2023-10-09T23:58:44.462Z] 23:58:44     INFO - test_page_nested_frames = 'https://web-platform.test:8443/webdriver/tests/support/inline.py?doc=%3C%21doctype+html%3E%0A%3Cmeta+charset%3DUTF-8%...253E%253C%252Fiframe%253E%26mime%3Dtext%252Fhtml%26charset%3DUTF-8%27%3E%3C%2Fiframe%3E&mime=text%2Fhtml&charset=UTF-8'
[task 2023-10-09T23:58:44.462Z] 23:58:44     INFO - test_page_same_origin_frame = 'https://web-platform.test:8443/webdriver/tests/support/inline.py?doc=%3C%21doctype+html%3E%0A%3Cmeta+charset%3DUTF-8%...253Efoo%253C%252Fdiv%253E%26mime%3Dtext%252Fhtml%26charset%3DUTF-8%27%3E%3C%2Fiframe%3E&mime=text%2Fhtml&charset=UTF-8'
[task 2023-10-09T23:58:44.462Z] 23:58:44     INFO - test_page = 'https://web-platform.test:8443/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-10-09T23:58:44.462Z] 23:58:44     INFO - 
[task 2023-10-09T23:58:44.462Z] 23:58:44     INFO -     async def test_nested_iframes(
[task 2023-10-09T23:58:44.462Z] 23:58:44     INFO -         bidi_session,
[task 2023-10-09T23:58:44.463Z] 23:58:44     INFO -         subscribe_events,
[task 2023-10-09T23:58:44.463Z] 23:58:44     INFO -         top_context,
[task 2023-10-09T23:58:44.463Z] 23:58:44     INFO -         test_page_nested_frames,
[task 2023-10-09T23:58:44.463Z] 23:58:44     INFO -         test_page_same_origin_frame,
[task 2023-10-09T23:58:44.463Z] 23:58:44     INFO -         test_page,
[task 2023-10-09T23:58:44.463Z] 23:58:44     INFO -     ):
[task 2023-10-09T23:58:44.463Z] 23:58:44     INFO -         events = []
[task 2023-10-09T23:58:44.463Z] 23:58:44     INFO -     
[task 2023-10-09T23:58:44.464Z] 23:58:44     INFO -         async def on_event(method, data):
[task 2023-10-09T23:58:44.464Z] 23:58:44     INFO -             events.append(data)
[task 2023-10-09T23:58:44.464Z] 23:58:44     INFO -     
[task 2023-10-09T23:58:44.464Z] 23:58:44     INFO -         remove_listener = bidi_session.add_event_listener(
[task 2023-10-09T23:58:44.464Z] 23:58:44     INFO -             NAVIGATION_STARTED_EVENT, on_event
[task 2023-10-09T23:58:44.464Z] 23:58:44     INFO -         )
[task 2023-10-09T23:58:44.464Z] 23:58:44     INFO -     
[task 2023-10-09T23:58:44.464Z] 23:58:44     INFO -         await subscribe_events(events=[NAVIGATION_STARTED_EVENT])
[task 2023-10-09T23:58:44.465Z] 23:58:44     INFO -     
[task 2023-10-09T23:58:44.465Z] 23:58:44     INFO -         result = await bidi_session.browsing_context.navigate(
[task 2023-10-09T23:58:44.465Z] 23:58:44     INFO -             context=top_context["context"], url=test_page_nested_frames, wait="complete"
[task 2023-10-09T23:58:44.465Z] 23:58:44     INFO -         )
[task 2023-10-09T23:58:44.465Z] 23:58:44     INFO -     
[task 2023-10-09T23:58:44.465Z] 23:58:44     INFO -         # Check that 3 navigation-started events were received, one for the top context
[task 2023-10-09T23:58:44.465Z] 23:58:44     INFO -         # and one for each of the 2 iframes.
[task 2023-10-09T23:58:44.465Z] 23:58:44     INFO - >       assert len(events) == 3
[task 2023-10-09T23:58:44.465Z] 23:58:44     INFO - E       assert 2 == 3
[task 2023-10-09T23:58:44.465Z] 23:58:44     INFO - E         +2
[task 2023-10-09T23:58:44.466Z] 23:58:44     INFO - E         -3
[task 2023-10-09T23:58:44.466Z] 23:58:44     INFO - 
[task 2023-10-09T23:58:44.466Z] 23:58:44     INFO - bidi_session = <webdriver.bidi.client.BidiSession object at 0x7f94b8f1c690>
[task 2023-10-09T23:58:44.466Z] 23:58:44     INFO - events     = [{'context': '17179869186',
[task 2023-10-09T23:58:44.466Z] 23:58:44     INFO -   'navigation': '9a49048f-3eef-4648-8bc1-5f05fcc77a70',
[task 2023-10-09T23:58:44.466Z] 23:58:44     INFO -   'timestamp': 1696895922385,
[task 2023-10-09T23:58:44.466Z] 23:58:44     INFO -   'url': 'https://web-platform.test:8443/webdriver/tests/support/inline.py?doc=%3C%21doctype+html%3E%0A%3Cmeta+charset%3DUTF-8%3E%0A%3Ciframe+src%3D%27https%3A%2F%2Fweb-platform.test%3A8443%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-10-09T23:58:44.466Z] 23:58:44     INFO -  {'context': '17179869187',
[task 2023-10-09T23:58:44.466Z] 23:58:44     INFO -   'navigation': 'c6e6cf33-e23f-47af-9f6d-8ded778c1a85',
[task 2023-10-09T23:58:44.467Z] 23:58:44     INFO -   'timestamp': 1696895922396,
[task 2023-10-09T23:58:44.467Z] 23:58:44     INFO -   'url': 'https://web-platform.test:8443/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-10-09T23:58:44.467Z] 23:58:44     INFO - on_event   = <function test_nested_iframes.<locals>.on_event at 0x7f94b8efd830>
[task 2023-10-09T23:58:44.467Z] 23:58:44     INFO - remove_listener = <function BidiSession.add_event_listener.<locals>.<lambda> at 0x7f94b8ef1dd0>
[task 2023-10-09T23:58:44.467Z] 23:58:44     INFO - result     = {'navigation': 'f356cfdd-0252-4a2a-bca5-85caccff7d67',
[task 2023-10-09T23:58:44.467Z] 23:58:44     INFO -  'url': 'https://web-platform.test:8443/webdriver/tests/support/inline.py?doc=%3C%21doctype+html%3E%0A%3Cmeta+charset%3DUTF-8%3E%0A%3Ciframe+src%3D%27https%3A%2F%2Fweb-platform.test%3A8443%2Fwebdriver%2Ftests%2Fsupport%2Finline.py%3Fdoc%3D%253C%2521doctype%2Bhtml%253E%250A%253Cmeta%2Bcharset%253DUTF-8%253E%250A%253Ciframe%2Bsrc%253D%2527https%253A%252F%252Fweb-platform.test%253A8443%252Fwebdriver%252Ftests%252Fsupport%252Finline.py%253Fdoc%253D%25253C%252521doctype%252Bhtml%25253E%25250A%25253Cmeta%252Bcharset%25253DUTF-8%25253E%25250A%25253Cdiv%25253Efoo%25253C%25252Fdiv%25253E%2526mime%253Dtext%25252Fhtml%2526charset%253DUTF-8%2527%253E%253C%252Fiframe%253E%26mime%3Dtext%252Fhtml%26charset%3DUTF-8%27%3E%3C%2Fiframe%3E&mime=text%2Fhtml&charset=UTF-8'}
[task 2023-10-09T23:58:44.467Z] 23:58:44     INFO - subscribe_events = <function subscribe_events.<locals>.subscribe_events at 0x7f94b8efdc20>
[task 2023-10-09T23:58:44.467Z] 23:58:44     INFO - test_page  = 'https://web-platform.test:8443/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-10-09T23:58:44.467Z] 23:58:44     INFO - test_page_nested_frames = 'https://web-platform.test:8443/webdriver/tests/support/inline.py?doc=%3C%21doctype+html%3E%0A%3Cmeta+charset%3DUTF-8%3E%0A%3Ciframe+src%3D%27https%3A%2F%2Fweb-platform.test%3A8443%2Fwebdriver%2Ftests%2Fsupport%2Finline.py%3Fdoc%3D%253C%2521doctype%2Bhtml%253E%250A%253Cmeta%2Bcharset%253DUTF-8%253E%250A%253Ciframe%2Bsrc%253D%2527https%253A%252F%252Fweb-platform.test%253A8443%252Fwebdriver%252Ftests%252Fsupport%252Finline.py%253Fdoc%253D%25253C%252521doctype%252Bhtml%25253E%25250A%25253Cmeta%252Bcharset%25253DUTF-8%25253E%25250A%25253Cdiv%25253Efoo%25253C%25252Fdiv%25253E%2526mime%253Dtext%25252Fhtml%2526charset%253DUTF-8%2527%253E%253C%252Fiframe%253E%26mime%3Dtext%252Fhtml%26charset%3DUTF-8%27%3E%3C%2Fiframe%3E&mime=text%2Fhtml&charset=UTF-8'
[task 2023-10-09T23:58:44.468Z] 23:58:44     INFO - test_page_same_origin_frame = 'https://web-platform.test:8443/webdriver/tests/support/inline.py?doc=%3C%21doctype+html%3E%0A%3Cmeta+charset%3DUTF-8%3E%0A%3Ciframe+src%3D%27https%3A%2F%2Fweb-platform.test%3A8443%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-10-09T23:58:44.468Z] 23:58:44     INFO - top_context = {'children': [{'children': [],
[task 2023-10-09T23:58:44.468Z] 23:58:44     INFO -                'context': '17179869185',
[task 2023-10-09T23:58:44.468Z] 23:58:44     INFO -                'url': 'https://web-platform.test:8443/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-10-09T23:58:44.468Z] 23:58:44     INFO -  'context': 'a2724788-0911-4843-9386-a2f7a0208120',
[task 2023-10-09T23:58:44.468Z] 23:58:44     INFO -  'parent': None,
[task 2023-10-09T23:58:44.468Z] 23:58:44     INFO -  'url': 'https://web-platform.test:8443/webdriver/tests/support/inline.py?doc=%3C%21doctype+html%3E%0A%3Cmeta+charset%3DUTF-8%3E%0A%3Ciframe+src%3D%27https%3A%2F%2Fweb-platform.test%3A8443%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-10-09T23:58:44.468Z] 23:58:44     INFO - 
[task 2023-10-09T23:58:44.468Z] 23:58:44     INFO - tests/web-platform/tests/webdriver/tests/bidi/browsing_context/navigation_started/navigation_started.py:168: AssertionError
[task 2023-10-09T23:58:44.472Z] 23:58:44     INFO - ........
[task 2023-10-09T23:58:44.472Z] 23:58:44     INFO - TEST-OK | /webdriver/tests/bidi/browsing_context/navigation_started/navigation_started.py | took 6095ms
[task 2023-10-09T23:58:44.472Z] 23:58:44     INFO - Restarting browser for new test group
[task 2023-10-09T23:58:44.474Z] 23:58:44     INFO - PID 1317 | 1696895924421	webdriver::server	DEBUG	-> GET /status
[task 2023-10-09T23:58:44.474Z] 23:58:44     INFO - PID 1317 | 1696895924421	webdriver::server	DEBUG	<- 200 OK {"value":{"message":"","ready":true}}
[task 2023-10-09T23:58:44.477Z] 23:58:44     INFO - Closing logging queue
[task 2023-10-09T23:58:44.477Z] 23:58:44     INFO - queue closed
[task 2023-10-09T23:58:44.658Z] 23:58:44     INFO - PID 1348 | 1696895924486	geckodriver	INFO	Listening on 127.0.0.1:50553
[task 2023-10-09T23:58:44.659Z] 23:58:44     INFO - Starting runner
[task 2023-10-09T23:58:45.116Z] 23:58:45     INFO - TEST-START | /webdriver/tests/bidi/browsing_context/set_viewport/invalid.py

It seems that we miss the navigation_started event for the top_context because the we didn't receive a navigation-stopped (internal for now) notification for the previous top_context navigation, from the previous test "test_iframe" done here.

At the beginning of test_iframe, the top context has browsing context id 4, and when we load the test URL, it goes through a remoteness change and switches to browsing context id 15 (note: I used the ids from the logs I investigated, but that's bound to be different for other runs).

The NavigationListener used by the NavigationManager will first capture a navigation-started for the BC 15, followed by a navigation-stopped. At that point we haven't received any navigation information from BC 4. But towards the end of the test we get a navigation-started from BC 4, quickly followed by a navigation-stopped with isBindingAborted set to true. We typically ignore such navigation-stopped, because they correspond to a process change and we expect to get the "real" navigation-stopped afterwards. But here it happened the other way around.

This means that when we start the next test, we still have a pending navigation for the top context, and we will therefore ignore the new navigation-started internal event "Skipping already tracked navigation, [...]".

One thing I avoided doing for now is to compare the URLs in the payloads of the navigation events. But we could probably do that: if we receive a navigation-started event for a navigable which already has a navigation tracked but for a different URL, we should assume this is a new navigation.

Status: NEW → RESOLVED
Closed: 1 year ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Summary: Intermittent [tier 2] /webdriver/tests/bidi/browsing_context/navigation_started/navigation_started.py | single tracking bug → Intermittent /webdriver/tests/bidi/browsing_context/navigation_started/navigation_started.py | single tracking bug
Attachment #9387587 - Attachment is obsolete: true
Status: REOPENED → RESOLVED
Closed: 1 year ago6 months ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 6 months ago2 months ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 2 months ago19 days ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---

(In reply to Treeherder Bug Filer from comment #41)

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

This was just bug 1924452.

Status: REOPENED → RESOLVED
Closed: 19 days ago11 days ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: