Closed Bug 1755242 Opened 3 years ago Closed 3 years ago

Intermittent TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/bidi/browsing_context/context_created/context_created.py | expected OK

Tracking

(firefox-esr91 unaffected, firefox97 unaffected, firefox98 unaffected, firefox99 fixed)

Status:

RESOLVED FIXED

Milestone:

99 Branch

Tracking Flags:

Tracking

Status

firefox-esr91

---

unaffected

firefox97

---

unaffected

firefox98

---

unaffected

firefox99

---

fixed

People

(Reporter: intermittent-bug-filer, Assigned: whimboo)

References

(Regression)

Details

(Keywords: intermittent-failure, regression, Whiteboard: [bidi-m3-mvp], [wptsync upstream])

Attachments

(1 file)

Bug 1755242 - [wdspec] Add AsyncPoll and fix race when awaiting multiple browsingContext.contextCreated events. 3 years ago Henrik Skupin [:whimboo][⌚️UTC+2] 48 bytes, text/x-phabricator-request		Details \| Review

Treeherder Bug Filer

Reporter

Description

•

3 years ago

treeherder

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

[task 2022-02-14T06:16:17.019Z] 06:16:17     INFO - TEST-START | /webdriver/tests/bidi/browsing_context/context_created/context_created.py
<...>
[task 2022-02-14T06:16:20.411Z] 06:16:20     INFO - PID 720 | 1644819380410	Marionette	TRACE	[49] Received event pageshow for http://web-platform.test:8000/webdriver/tests/support/inline.py?doc=%3C%21doctype+html%3E%0A%3Cmeta+charset%3DUTF-8%3E%0A%3Ci ... DUTF-8%2527%253E%253C%252Fiframe%26mime%3Dtext%252Fhtml%26charset%3DUTF-8%27%3E%3C%2Fiframe%3E&mime=text%2Fhtml&charset=UTF-8
[task 2022-02-14T06:16:20.411Z] 06:16:20     INFO - PID 720 | 1644819380410	Marionette	DEBUG	0 <- [1,133,null,{"value":null}]
[task 2022-02-14T06:16:20.412Z] 06:16:20     INFO - PID 720 | 1644819380411	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2022-02-14T06:16:20.600Z] 06:16:20     INFO - PID 720 | 1644819380600	RemoteAgent	TRACE	[12884901891] No navigation detected: http://web-platform.test:8000/webdriver/tests/support/inline.py?doc=%3C%21doctype+html%3E%0A%3Cmeta+charset%3DUTF-8%3E%0A%3Ci ... A%253Cdiv%253Efoo%253C%252Fdiv%253E%26mime%3Dtext%252Fhtml%26charset%3DUTF-8%27%3E%3C%2Fiframe&mime=text%2Fhtml&charset=UTF-8
[task 2022-02-14T06:16:20.603Z] 06:16:20     INFO - PID 720 | 1644819380601	WebDriver BiDi	DEBUG	7e27754d-29a9-4437-bfe8-759bb0db75d2 <- {"method":"browsingContext.contextCreated","params":{"context":"12884901891","url":"http://web-platform.test:8000/webdriver/t ... t%3DUTF-8%27%3E%3C%2Fiframe&mime=text%2Fhtml&charset=UTF-8","children":null,"parent":"07bc1cd7-4e93-4cc5-b4de-609191f18260"}}
[task 2022-02-14T06:16:20.603Z] 06:16:20     INFO - PID 720 | 1644819380601	RemoteAgent	TRACE	[12884901892] No navigation detected: 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 2022-02-14T06:16:20.604Z] 06:16:20     INFO - PID 720 | 1644819380601	WebDriver BiDi	DEBUG	7e27754d-29a9-4437-bfe8-759bb0db75d2 <- {"method":"browsingContext.contextCreated","params":{"context":"12884901892","url":"http://web-platform.test:8000/webdriver/t ... 3Cmeta+charset%3DUTF-8%3E%0A%3Cdiv%3Efoo%3C%2Fdiv%3E&mime=text%2Fhtml&charset=UTF-8","children":null,"parent":"12884901891"}}
[task 2022-02-14T06:16:47.034Z] 06:16:47     INFO - TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/bidi/browsing_context/context_created/context_created.py | expected OK
[task 2022-02-14T06:16:47.037Z] 06:16:47     INFO - TEST-INFO took 30015ms
[task 2022-02-14T06:16:47.039Z] 06:16:47     INFO - PID 720 | 1644819407037	webdriver::server	DEBUG	-> GET /status
[task 2022-02-14T06:16:47.040Z] 06:16:47     INFO - PID 720 | 1644819407038	webdriver::server	DEBUG	<- 200 OK {"value":{"message":"Session already started","ready":false}}
[task 2022-02-14T06:16:48.054Z] 06:16:48     INFO - PID 720 | 1644819408055	webdriver::server	DEBUG	-> GET /status
[task 2022-02-14T06:16:48.057Z] 06:16:48     INFO - PID 720 | 1644819408055	webdriver::server	DEBUG	<- 200 OK {"value":{"message":"Session already started","ready":false}}
[task 2022-02-14T06:16:49.057Z] 06:16:49     INFO - PID 720 | 1644819409059	webdriver::server	DEBUG	-> GET /status
[task 2022-02-14T06:16:49.061Z] 06:16:49     INFO - PID 720 | 1644819409059	webdriver::server	DEBUG	<- 200 OK {"value":{"message":"Session already started","ready":false}}
[task 2022-02-14T06:16:50.061Z] 06:16:50     INFO - PID 720 | 1644819410062	webdriver::server	DEBUG	-> GET /status
<...>
[task 2022-02-14T06:17:56.355Z] 06:17:56     INFO - PID 720 | 1644819476353	webdriver::server	DEBUG	<- 200 OK {"value":{"message":"Session already started","ready":false}}
[task 2022-02-14T06:18:07.409Z] 06:18:07  WARNING - Forcibly terminating runner process
[task 2022-02-14T06:18:07.928Z] 06:18:07     INFO - PID 7904 | 1644819487430	geckodriver	INFO	Listening on 127.0.0.1:49825
[task 2022-02-14T06:18:07.930Z] 06:18:07     INFO - Starting runner
[task 2022-02-14T06:18:08.514Z] 06:18:08     INFO - TEST-START | /webdriver/tests/bidi/errors/errors.py

Atila Butkovits

Comment 1

•

3 years ago

Started failing on t1 jobs: https://treeherder.mozilla.org/logviewer?job_id=367776244&repo=autoland&lineNumber=3383

Summary: Intermittent [tier 2] TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/bidi/browsing_context/context_created/context_created.py | expected OK → Intermittent TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/bidi/browsing_context/context_created/context_created.py | expected OK

Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)

Updated

•

3 years ago

Component: web-platform-tests → geckodriver

Henrik Skupin [:whimboo][⌚️UTC+2]

Assignee

Comment 2

•

3 years ago

This is an interesting one:

https://treeherder.mozilla.org/logviewer?job_id=367772032&repo=autoland&lineNumber=2965-2984

[task 2022-02-14T06:16:20.374Z] 06:16:20     INFO - PID 720 | 1644819380365	webdriver::server	DEBUG	-> POST /session/7e27754d-29a9-4437-bfe8-759bb0db75d2/url {"url": "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%253Ciframe%2Bsrc%253D%2527http%253A%252F%252Fweb-platform.test%253A8000%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%26mime%3Dtext%252Fhtml%26charset%3DUTF-8%27%3E%3C%2Fiframe%3E&mime=text%2Fhtml&charset=UTF-8"}
[task 2022-02-14T06:16:20.375Z] 06:16:20     INFO - PID 720 | 1644819380366	Marionette	DEBUG	0 -> [0,133,"WebDriver:Navigate",{"url":"http://web-platform.test:8000/webdriver/tests/support/inline.py?doc=%3C%21doctype+html%3E ... F-8%2527%253E%253C%252Fiframe%26mime%3Dtext%252Fhtml%26charset%3DUTF-8%27%3E%3C%2Fiframe%3E&mime=text%2Fhtml&charset=UTF-8"}]
[task 2022-02-14T06:16:20.376Z] 06:16:20     INFO - PID 720 | 1644819380368	Marionette	TRACE	[47] Received event beforeunload for http://web-platform.test:8000/webdriver/tests/support/inline.py?doc=%3C%21doctype+html%3E%0A%3Cmeta+charset%3DUTF-8%3E%0A%3Ci ... 53Cdiv%253Ebar%253C%252Fdiv%253E%26mime%3Dtext%252Fhtml%26charset%3DUTF-8%27%3E%3C%2Fiframe%3E&mime=text%2Fhtml&charset=UTF-8
[task 2022-02-14T06:16:20.377Z] 06:16:20     INFO - PID 720 | 1644819380376	Marionette	TRACE	Remoteness change detected. Set new top-level browsing context to 49
[task 2022-02-14T06:16:20.378Z] 06:16:20     INFO - PID 720 | 1644819380377	RemoteAgent	TRACE	Created MessageHandler WINDOW_GLOBAL for session 7e27754d-29a9-4437-bfe8-759bb0db75d2
[task 2022-02-14T06:16:20.380Z] 06:16:20     INFO - PID 720 | 1644819380379	Marionette	TRACE	[49] Received event beforeunload for about:blank
[task 2022-02-14T06:16:20.381Z] 06:16:20     INFO - PID 720 | 1644819380381	Marionette	TRACE	[49] Received event pagehide for about:blank
[task 2022-02-14T06:16:20.383Z] 06:16:20     INFO - PID 720 | 1644819380382	RemoteAgent	TRACE	Created MessageHandler WINDOW_GLOBAL for session 7e27754d-29a9-4437-bfe8-759bb0db75d2
[task 2022-02-14T06:16:20.383Z] 06:16:20     INFO - PID 720 | 1644819380383	RemoteAgent	TRACE	MessageHandler WINDOW_GLOBAL for session 7e27754d-29a9-4437-bfe8-759bb0db75d2 is being destroyed
[task 2022-02-14T06:16:20.384Z] 06:16:20     INFO - PID 720 | 1644819380383	RemoteAgent	TRACE	Unregistered MessageHandler WINDOW_GLOBAL for session 7e27754d-29a9-4437-bfe8-759bb0db75d2
[task 2022-02-14T06:16:20.387Z] 06:16:20     INFO - PID 720 | 1644819380387	RemoteAgent	TRACE	Created MessageHandler WINDOW_GLOBAL for session 7e27754d-29a9-4437-bfe8-759bb0db75d2
[task 2022-02-14T06:16:20.391Z] 06:16:20     INFO - PID 720 | 1644819380390	Marionette	TRACE	[49] Received event DOMContentLoaded for http://web-platform.test:8000/webdriver/tests/support/inline.py?doc=%3C%21doctype+html%3E%0A%3Cmeta+charset%3DUTF-8%3E%0A%3Ci ... DUTF-8%2527%253E%253C%252Fiframe%26mime%3Dtext%252Fhtml%26charset%3DUTF-8%27%3E%3C%2Fiframe%3E&mime=text%2Fhtml&charset=UTF-8
[task 2022-02-14T06:16:20.402Z] 06:16:20     INFO - PID 720 | 1644819380402	RemoteAgent	TRACE	Created MessageHandler WINDOW_GLOBAL for session 7e27754d-29a9-4437-bfe8-759bb0db75d2
[task 2022-02-14T06:16:20.411Z] 06:16:20     INFO - PID 720 | 1644819380410	Marionette	TRACE	[49] Received event pageshow for http://web-platform.test:8000/webdriver/tests/support/inline.py?doc=%3C%21doctype+html%3E%0A%3Cmeta+charset%3DUTF-8%3E%0A%3Ci ... DUTF-8%2527%253E%253C%252Fiframe%26mime%3Dtext%252Fhtml%26charset%3DUTF-8%27%3E%3C%2Fiframe%3E&mime=text%2Fhtml&charset=UTF-8
[task 2022-02-14T06:16:20.411Z] 06:16:20     INFO - PID 720 | 1644819380410	Marionette	DEBUG	0 <- [1,133,null,{"value":null}]
[task 2022-02-14T06:16:20.412Z] 06:16:20     INFO - PID 720 | 1644819380411	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2022-02-14T06:16:20.600Z] 06:16:20     INFO - PID 720 | 1644819380600	RemoteAgent	TRACE	[12884901891] No navigation detected: http://web-platform.test:8000/webdriver/tests/support/inline.py?doc=%3C%21doctype+html%3E%0A%3Cmeta+charset%3DUTF-8%3E%0A%3Ci ... A%253Cdiv%253Efoo%253C%252Fdiv%253E%26mime%3Dtext%252Fhtml%26charset%3DUTF-8%27%3E%3C%2Fiframe&mime=text%2Fhtml&charset=UTF-8
[task 2022-02-14T06:16:20.603Z] 06:16:20     INFO - PID 720 | 1644819380601	WebDriver BiDi	DEBUG	7e27754d-29a9-4437-bfe8-759bb0db75d2 <- {"method":"browsingContext.contextCreated","params":{"context":"12884901891","url":"http://web-platform.test:8000/webdriver/t ... t%3DUTF-8%27%3E%3C%2Fiframe&mime=text%2Fhtml&charset=UTF-8","children":null,"parent":"07bc1cd7-4e93-4cc5-b4de-609191f18260"}}
[task 2022-02-14T06:16:20.603Z] 06:16:20     INFO - PID 720 | 1644819380601	RemoteAgent	TRACE	[12884901892] No navigation detected: 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 2022-02-14T06:16:20.604Z] 06:16:20     INFO - PID 720 | 1644819380601	WebDriver BiDi	DEBUG	7e27754d-29a9-4437-bfe8-759bb0db75d2 <- {"method":"browsingContext.contextCreated","params":{"context":"12884901892","url":"http://web-platform.test:8000/webdriver/t ... 3Cmeta+charset%3DUTF-8%3E%0A%3Cdiv%3Efoo%3C%2Fdiv%3E&mime=text%2Fhtml&charset=UTF-8","children":null,"parent":"12884901891"}}

As we can see we get the browsingContext.contextCreated event emitted twice for both frames but we somehow miss to receive it in the test. I assume that setting up the test like the following is causing the problem:

    frame_info = await wait_for_event(CONTEXT_CREATED_EVENT)
    [..]
    nested_frame_info = await wait_for_event(CONTEXT_CREATED_EVENT)

We may have to setup a general listener which handles each and every event and not causing race conditions by setting up the event listener too late. Then we can wait for the amount of events actually emitted.

Henrik Skupin [:whimboo][⌚️UTC+2]

Assignee

Comment 3

•

3 years ago

This is a new test and started to fail with the landing of the patch on bug 1694389.

Points: --- → 2

status-firefox97: --- → unaffected

status-firefox98: --- → unaffected

status-firefox99: --- → affected

status-firefox-esr91: --- → unaffected

Regressed by: 1694389

Whiteboard: [bidi-m3-mvp]

Henrik Skupin [:whimboo][⌚️UTC+2]

Assignee

Comment 4

•

3 years ago

Attached file Bug 1755242 - [wdspec] Add AsyncPoll and fix race when awaiting multiple browsingContext.contextCreated events. — Details

Phabricator Automation

Updated

•

3 years ago

Assignee: nobody → hskupin

Status: NEW → ASSIGNED

Marco Mucci [:MarcoM]

Updated

•

3 years ago

Priority: P5 → P2

BugBot [:suhaib / :marco/ :calixte]

Updated

•

3 years ago

Has Regression Range: --- → yes

Pulsebot

Comment 5

•

3 years ago

Pushed by hskupin@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/18397fa31ca2 [wdspec] Add AsyncPoll and fix race when awaiting multiple browsingContext.contextCreated events. r=webdriver-reviewers,jgraham

Web Platform Test Sync Bot [:wpt-sync] (Matrix: #interop:mozilla.org)

Comment 6

•

3 years ago

Created web-platform-tests PR https://github.com/web-platform-tests/wpt/pull/32859 for changes under testing/web-platform/tests

Web Platform Test Sync Bot [:wpt-sync] (Matrix: #interop:mozilla.org)

Updated

•

3 years ago

Whiteboard: [bidi-m3-mvp] → [bidi-m3-mvp], [wptsync upstream]

Web Platform Test Sync Bot [:wpt-sync] (Matrix: #interop:mozilla.org)

Comment 7

•

3 years ago

Upstream PR merged by moz-wptsync-bot

Natalia Csoregi [:nataliaCs]

Comment 8

•

3 years ago

bugherder

https://hg.mozilla.org/mozilla-central/rev/18397fa31ca2

Status: ASSIGNED → RESOLVED

Closed: 3 years ago

status-firefox99: affected → fixed

Resolution: --- → FIXED

Target Milestone: --- → 99 Branch

Comment hidden (Intermittent Failures Robot)

BugBot [:suhaib / :marco/ :calixte]

Updated

•

3 years ago

Keywords: regression

BMO Automation

Comment 10

•

2 years ago

Moving bug to Remote Protocol::Marionette component per bug 1815831.

Component: geckodriver → Marionette

Product: Testing → Remote Protocol

You need to log in before you can comment on or make changes to this bug.

Bugzilla

Intermittent TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/bidi/browsing_context/context_created/context_created.py | expected OK

Categories

(Remote Protocol :: Marionette, defect, P2)

Tracking

(firefox-esr91 unaffected, firefox97 unaffected, firefox98 unaffected, firefox99 fixed)

People

(Reporter: intermittent-bug-filer, Assigned: whimboo)

References

(Regression)

Details

(Keywords: intermittent-failure, regression, Whiteboard: [bidi-m3-mvp], [wptsync upstream])

Crash Data

Security

(public)

User Story

Attachments

(1 file)

Description

Comment 1

Updated

Comment 2

Comment 3

Comment 4

Updated

Updated

Updated

Comment 5

Comment 6

Updated

Comment 7

Comment 8

Comment 9

Updated

Comment 10

Attachment

General

Description

File Name

Content Type