1460060 - Intermittent TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/new_session/create_firstMatch.py | expected OK

Status: RESOLVED DUPLICATE of bug 1419176

(Remote Protocol :: Marionette, defect, P5)

Description

[Treeherder Bug Filer]

Filed by: apavel [at] mozilla.com

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

https://queue.taskcluster.net/v1/task/Fvuq5O-1SNuSiQElKC2aig/runs/0/artifacts/public/logs/live_backing.log

[task 2018-05-08T21:11:59.940Z] 21:11:59     INFO - PID 8243 | console.error: PushService:
[task 2018-05-08T21:11:59.941Z] 21:11:59     INFO - PID 8243 |   clearOriginData: Error clearing origin data:
[task 2018-05-08T21:11:59.942Z] 21:11:59     INFO - PID 8243 |   UnknownError
[task 2018-05-08T21:11:59.943Z] 21:11:59     INFO - PID 8243 | console.error: PushService:
[task 2018-05-08T21:11:59.943Z] 21:11:59     INFO - PID 8243 |   stateChangeProcessEnqueue: Error transitioning state
[task 2018-05-08T21:11:59.945Z] 21:11:59     INFO - PID 8243 |   UnknownError
[task 2018-05-08T21:11:59.946Z] 21:11:59     INFO - PID 8243 | 
[task 2018-05-08T21:11:59.947Z] 21:11:59     INFO - PID 8243 | ###!!! [Parent][DispatchAsyncMessage] Error: PBackgroundIDBFactory::Msg_PBackgroundIDBFactoryRequestConstructor Value error: message was deserialized, but contained an illegal value
[task 2018-05-08T21:11:59.949Z] 21:11:59     INFO - PID 8243 | 
[task 2018-05-08T21:11:59.950Z] 21:11:59     INFO - PID 8243 | 
[task 2018-05-08T21:11:59.950Z] 21:11:59     INFO - PID 8243 | ###!!! [Parent][DispatchAsyncMessage] Error: PBackgroundIDBFactory::Msg_PBackgroundIDBFactoryRequestConstructor Value error: message was deserialized, but contained an illegal value
[task 2018-05-08T21:11:59.951Z] 21:11:59     INFO - PID 8243 | 
[task 2018-05-08T21:11:59.975Z] 21:11:59     INFO - PID 8243 | *** UTM:SVC TimerManager:registerTimer called after profile-before-change notification. Ignoring timer registration for id: telemetry_modules_ping
[task 2018-05-08T21:12:00.064Z] 21:12:00     INFO - PID 8243 | 1525813920060	Marionette	DEBUG	Received observer notification xpcom-will-shutdown
[task 2018-05-08T21:12:00.064Z] 21:12:00     INFO - PID 8243 | 1525813920060	Marionette	DEBUG	Resetting recommended pref toolkit.cosmeticAnimations.enabled
[task 2018-05-08T21:12:00.065Z] 21:12:00     INFO - PID 8243 | 1525813920061	Marionette	DEBUG	Resetting recommended pref datareporting.policy.dataSubmissionPolicyAccepted
[task 2018-05-08T21:12:00.410Z] 21:12:00     INFO - PID 8243 | 1525813920406	geckodriver::marionette	DEBUG	Browser process stopped: exit code: 0
[task 2018-05-08T21:12:00.415Z] 21:12:00     INFO - PID 8243 | 1525813920411	webdriver::server	DEBUG	<- 200 OK {"value": {}}
[task 2018-05-08T21:12:00.417Z] 21:12:00     INFO - STDOUT: tests/web-platform/tests/webdriver/tests/new_session/create_firstMatch.py::test_valid[test:extension-None] 
[task 2018-05-08T21:12:00.420Z] 21:12:00     INFO - PID 8243 | 1525813920416	webdriver::server	DEBUG	-> POST /session {"capabilities": {"firstMatch": [{"moz:firefoxOptions": {"binary": "/builds/worker/workspace/build/application/firefox/firefox", "prefs": {"network.dns.localDomains": "web-platform.test,www.web-platform.test,xn--n8j6ds53lwwkrqhv28a.web-platform.test,xn--lve-6lad.web-platform.test,www2.web-platform.test,www1.web-platform.test"}}, "test:extension": null}]}}
[task 2018-05-08T21:12:00.423Z] 21:12:00     INFO - PID 8243 | 1525813920419	mozrunner::runner	INFO	Running command: "/builds/worker/workspace/build/application/firefox/firefox" "-marionette" "-profile" "/tmp/rust_mozprofile.AUbGXV5agdqq"
[task 2018-05-08T21:12:00.427Z] 21:12:00     INFO - PID 8243 | 1525813920424	geckodriver::marionette	DEBUG	Waiting 60s to connect to browser
[task 2018-05-08T21:12:00.767Z] 21:12:00     INFO - TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/new_session/create_firstMatch.py | expected OK
[task 2018-05-08T21:12:00.767Z] 21:12:00     INFO - TEST-INFO took 125002ms
[task 2018-05-08T21:12:01.180Z] 21:12:01  WARNING - u'runner_teardown': ()
[task 2018-05-08T21:12:01.182Z] 21:12:01     INFO - Starting runner
[task 2018-05-08T21:12:01.207Z] 21:12:01     INFO - PID 14035 | 1525813921202	geckodriver	INFO	geckodriver 0.20.1 ( '3b84be9ee9e6'  '2018-05-07 15:05 -0700')
[task 2018-05-08T21:12:01.207Z] 21:12:01     INFO - PID 14035 | 1525813921202	webdriver::httpapi	DEBUG	Creating routes
[task 2018-05-08T21:12:01.211Z] 21:12:01     INFO - PID 14035 | 1525813921206	geckodriver	INFO	Listening on 127.0.0.1:4444
[task 2018-05-08T21:12:01.712Z] 21:12:01     INFO - WebDriver HTTP server listening at http://127.0.0.1:4444/

Comment 1

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

The tests restart Firefox a lot and I can see slow startup times of Firefox. Lets wait for some more data.

Comment 3

[Intermittent Failures Robot]

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

Repository breakdown:
* autoland: 1

Platform breakdown:
* linux32: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1460060&startday=2018-05-07&endday=2018-05-13&tree=trunk

Comment 4

[Intermittent Failures Robot]

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

Repository breakdown:
* mozilla-inbound: 1

Platform breakdown:
* linux64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1460060&startday=2018-08-20&endday=2018-08-26&tree=all

Comment 5

[BMO Automation]

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