Closed Bug 1460048 Opened 6 years ago Closed 6 years ago

Intermittent TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/get_element_property/user_prompts.py | expected OK

Categories

(Remote Protocol :: Marionette, defect, P5)

Version 3
defect

Tracking

(firefox62 disabled)

RESOLVED WORKSFORME
Tracking Status
firefox62 --- disabled

People

(Reporter: intermittent-bug-filer, Unassigned)

References

(Depends on 1 open bug)

Details

(Keywords: intermittent-failure, Whiteboard: [retriggered][webrender])

Filed by: apavel [at] mozilla.com

https://treeherder.mozilla.org/logviewer.html#?job_id=177533609&repo=autoland

https://queue.taskcluster.net/v1/task/LnM76Q6ZSyKS59Hsa6i7qQ/runs/0/artifacts/public/logs/live_backing.log

task 2018-05-08T19:37:54.566Z] 19:37:54     INFO - PID 4005 | 1525808274545	webdriver::server	DEBUG	-> POST /session/da5776db-c9a5-40a4-8135-7abd36032dc2/window {"handle": "2147483649"}
[task 2018-05-08T19:37:54.567Z] 19:37:54     INFO - PID 4005 | 1525808274545	geckodriver::marionette	TRACE	-> 55:[0,21,"WebDriver:SwitchToWindow",{"name":"2147483649"}]
[task 2018-05-08T19:37:54.568Z] 19:37:54     INFO - PID 4005 | 1525808274550	Marionette	TRACE	0 -> [0,21,"WebDriver:SwitchToWindow",{"name":"2147483649"}]
[task 2018-05-08T19:37:54.572Z] 19:37:54     INFO - PID 4005 | 1525808274551	Marionette	TRACE	0 <- [1,21,null,{}]
[task 2018-05-08T19:37:54.575Z] 19:37:54     INFO - PID 4005 | 1525808274551	geckodriver::marionette	TRACE	<- [1,21,null,{}]
[task 2018-05-08T19:37:54.576Z] 19:37:54     INFO - PID 4005 | 1525808274552	webdriver::server	DEBUG	<- 200 OK {"value": {}}
[task 2018-05-08T19:37:54.577Z] 19:37:54     INFO - PID 4005 | 1525808274554	webdriver::server	DEBUG	-> GET /session/da5776db-c9a5-40a4-8135-7abd36032dc2/window
[task 2018-05-08T19:37:54.578Z] 19:37:54     INFO - PID 4005 | 1525808274554	geckodriver::marionette	TRACE	-> 37:[0,22,"WebDriver:GetWindowHandle",{}]
[task 2018-05-08T19:37:54.579Z] 19:37:54     INFO - PID 4005 | 1525808274559	Marionette	TRACE	0 -> [0,22,"WebDriver:GetWindowHandle",{}]
[task 2018-05-08T19:37:54.581Z] 19:37:54     INFO - PID 4005 | 1525808274560	Marionette	TRACE	0 <- [1,22,null,{"value":"2147483649"}]
[task 2018-05-08T19:37:54.581Z] 19:37:54     INFO - PID 4005 | 1525808274561	geckodriver::marionette	TRACE	<- [1,22,null,{"value":"2147483649"}]
[task 2018-05-08T19:37:54.582Z] 19:37:54     INFO - PID 4005 | 1525808274561	webdriver::server	DEBUG	<- 200 OK {"value":"2147483649"}
[task 2018-05-08T19:37:54.583Z] 19:37:54     INFO - PID 4005 | 1525808274563	webdriver::server	DEBUG	-> GET /session/da5776db-c9a5-40a4-8135-7abd36032dc2/window/handles
[task 2018-05-08T19:37:54.584Z] 19:37:54     INFO - PID 4005 | 1525808274564	geckodriver::marionette	TRACE	-> 38:[0,23,"WebDriver:GetWindowHandles",{}]
[task 2018-05-08T19:37:54.585Z] 19:37:54     INFO - TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/get_element_property/user_prompts.py | expected OK
[task 2018-05-08T19:37:54.586Z] 19:37:54     INFO - TEST-INFO took 30003ms
[task 2018-05-08T19:37:54.645Z] 19:37:54     INFO - PID 4005 | 1525808274568	Marionette	TRACE	0 -> [0,23,"WebDriver:GetWindowHandles",{}]
[task 2018-05-08T19:37:54.645Z] 19:37:54     INFO - PID 4005 | 1525808274569	Marionette	TRACE	0 <- [1,23,null,["2147483649"]]
[task 2018-05-08T19:37:54.646Z] 19:37:54     INFO - PID 4005 | 1525808274569	geckodriver::marionette	TRACE	<- [1,23,null,["2147483649"]]
[task 2018-05-08T19:37:54.646Z] 19:37:54     INFO - PID 4005 | 1525808274569	webdriver::server	DEBUG	<- 200 OK {"value":["2147483649"]}
[task 2018-05-08T19:37:54.647Z] 19:37:54     INFO - PID 4005 | 1525808274572	webdriver::server	DEBUG	-> POST /session/da5776db-c9a5-40a4-8135-7abd36032dc2/window {"handle": "2147483649"}
[task 2018-05-08T19:37:54.647Z] 19:37:54     INFO - PID 4005 | 1525808274573	geckodriver::marionette	TRACE	-> 55:[0,24,"WebDriver:SwitchToWindow",{"name":"2147483649"}]
[task 2018-05-08T19:37:54.647Z] 19:37:54  WARNING - u'runner_teardown': ()
[task 2018-05-08T19:37:54.648Z] 19:37:54     INFO - Starting runner
[task 2018-05-08T19:37:54.668Z] 19:37:54     INFO - PID 4684 | 1525808274663	geckodriver	INFO	geckodriver 0.20.1 ( '6d595a423fb5'  '2018-04-30 12:49 -0700')
[task 2018-05-08T19:37:54.668Z] 19:37:54     INFO - PID 4684 | 1525808274663	webdriver::httpapi	DEBUG	Creating routes
[task 2018-05-08T19:37:54.672Z] 19:37:54     INFO - PID 4684 | 1525808274667	geckodriver	INFO	Listening on 127.0.0.1:4445
[task 2018-05-08T19:37:55.172Z] 19:37:55     INFO - WebDriver HTTP server listening at http://127.0.0.1:4445/
There is a delay of 5s in initializing Marionette for each startup of Firefox. I filed bug 1460193 to get this investigated.

If it turns out that it fails too often we will have to increase the timeout.
Depends on: 1460193
(In reply to Tiberius Oros[:tiberius_oros] from comment #2)
> and noticed that the culprit is this push:
> https://treeherder.mozilla.org/#/
> jobs?repo=autoland&revision=6d595a423fb52766abb5c1d10d4b9d7d6027d68a&filter-
> searchStr=debug-web-platform-tests-wdspec-e10s
> 
> all other failures on previous pushes ar not on the same test file.

I don't think so. You just hit this failure a single time which is not an indication that this is the causing push. It's a low-frequent intermittent one. I did a reorganization of the tests lately and as such this new bug has been filed.
The test needs to be disabled for webrender. It will be done on bug 1461253.
Depends on: 1461253
Keywords: test-disabled
Whiteboard: [retriggered] → [retriggered][webrender]

At some point this test file got unskipped. It's working fine right now.

Keywords: test-disabled
Resolution: INCOMPLETE → WORKSFORME
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.