Closed Bug 1574837 Opened 5 years ago Closed 4 years ago

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

Categories

(Remote Protocol :: Marionette, defect, P5)

Version 3
x86_64
Linux
defect

Tracking

(firefox69 unaffected, firefox70 fix-optional, firefox71 fix-optional, firefox72 ?)

RESOLVED INCOMPLETE
Tracking Status
firefox69 --- unaffected
firefox70 --- fix-optional
firefox71 --- fix-optional
firefox72 --- ?

People

(Reporter: intermittent-bug-filer, Unassigned)

References

Details

(Keywords: intermittent-failure, regression, Whiteboard: [stockwell unknown])

Filed by: malexandru [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=262193308&repo=mozilla-central
Full log: https://queue.taskcluster.net/v1/task/Uffz5j23RMGZehzqmY2vTg/runs/0/artifacts/public/logs/live_backing.log


[task 2019-08-18T23:30:42.404Z] 23:30:42 INFO - PID 26065 | 1566171042398 Marionette INFO Listening on port 2828
[task 2019-08-18T23:30:42.405Z] 23:30:42 INFO - PID 26065 | 1566171042398 Marionette DEBUG Remote service is active
[task 2019-08-18T23:30:42.413Z] 23:30:42 INFO - PID 26065 | 1566171042408 geckodriver::marionette DEBUG Connection established on 127.0.0.1:2828. Waiting for Marionette handshake
[task 2019-08-18T23:30:42.414Z] 23:30:42 INFO - PID 26065 | 1566171042410 Marionette DEBUG Accepted connection 0 from 127.0.0.1:44698
[task 2019-08-18T23:30:42.416Z] 23:30:42 INFO - PID 26065 | 1566171042411 geckodriver::marionette DEBUG Connected to Marionette
[task 2019-08-18T23:30:42.420Z] 23:30:42 INFO - PID 26065 | 1566171042414 Marionette DEBUG 0 -> [0,1,"WebDriver:NewSession",{"timeouts":{"implicit":0,"pageLoad":300000,"script":null}}]
[task 2019-08-18T23:30:42.461Z] 23:30:42 INFO - PID 26065 | 1566171042455 Marionette TRACE [18] Frame script loaded
[task 2019-08-18T23:30:42.462Z] 23:30:42 INFO - PID 26065 | 1566171042457 Marionette TRACE [18] Frame script registered
[task 2019-08-18T23:30:42.470Z] 23:30:42 INFO - PID 26065 | 1566171042464 Marionette DEBUG 0 <- [1,1,null,{"sessionId":"e6911cfe-ec62-466b-8de1-ac177e213cc5","capabilities":{"browserName":"firefox","browserVersion":"70.0a ... /rust_mozprofileSWW1CJ","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true}}]
[task 2019-08-18T23:30:42.471Z] 23:30:42 INFO - STDOUT: PASSED
[task 2019-08-18T23:30:42.473Z] 23:30:42 INFO - PID 26065 | 1566171042467 webdriver::server DEBUG <- 200 OK {"value":{"sessionId":"e6911cfe-ec62-466b-8de1-ac177e213cc5","capabilities":{"acceptInsecureCerts":false,"browserName":"firefox","browserVersion":"70.0a1","moz:accessibilityChecks":false,"moz:buildID":"20190818215144","moz:geckodriverVersion":"0.24.0","moz:headless":false,"moz:processID":6143,"moz:profile":"/tmp/rust_mozprofileSWW1CJ","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true,"pageLoadStrategy":"normal","platformName":"linux","platformVersion":"4.4.0-1014-aws","rotatable":false,"setWindowRect":true,"strictFileInteractability":false,"timeouts":{"implicit":0,"pageLoad":300000,"script":null},"unhandledPromptBehavior":"dismiss and notify"}}}
[task 2019-08-18T23:30:42.475Z] 23:30:42 INFO - PID 26065 | 1566171042469 webdriver::server DEBUG -> DELETE /session/e6911cfe-ec62-466b-8de1-ac177e213cc5
[task 2019-08-18T23:30:42.476Z] 23:30:42 INFO - PID 26065 | 1566171042472 Marionette DEBUG 0 -> [0,2,"Marionette:Quit",{"flags":["eForceQuit"]}]
[task 2019-08-18T23:30:42.477Z] 23:30:42 INFO - PID 26065 | 1566171042472 Marionette INFO Stopped listening on port 2828
[task 2019-08-18T23:30:42.534Z] 23:30:42 INFO - PID 26065 | 1566171042529 Marionette TRACE Received observer notification quit-application
[task 2019-08-18T23:30:42.539Z] 23:30:42 INFO - PID 26065 | 1566171042536 Marionette DEBUG 0 <- [1,2,null,{"cause":"shutdown"}]
[task 2019-08-18T23:30:42.575Z] 23:30:42 INFO - PID 26065 | 1566171042569 webdriver::server DEBUG Deleting session
[task 2019-08-18T23:30:42.583Z] 23:30:42 INFO - PID 26065 | 1566171042577 Marionette DEBUG 0 -> [0,3,"Marionette:Quit",{"flags":["eForceQuit"]}]
[task 2019-08-18T23:30:42.591Z] 23:30:42 INFO - PID 26065 | 1566171042578 Marionette DEBUG 0 <- [1,3,{"error":"invalid session id","message":"Tried to run command without establishing a connection","stacktrace":"WebDriver ... t@chrome://marionette/content/server.js:249:9\n_onJSONObjectReady/<@chrome://marionette/content/transport.js:503:20\n"},null]
[task 2019-08-18T23:30:42.591Z] 23:30:42 INFO - PID 26065 | 1566171042585 Marionette DEBUG Closed connection 0
[task 2019-08-18T23:30:45.723Z] 23:30:45 INFO - PID 26065 | 1566171045717 Marionette TRACE Received observer notification xpcom-will-shutdown
[task 2019-08-18T23:30:45.725Z] 23:30:45 INFO - PID 26065 | 1566171045717 Marionette DEBUG Resetting recommended pref apz.content_response_timeout
[task 2019-08-18T23:30:45.725Z] 23:30:45 INFO - PID 26065 | 1566171045717 Marionette DEBUG Resetting recommended pref browser.contentblocking.introCount
[task 2019-08-18T23:30:45.727Z] 23:30:45 INFO - PID 26065 | 1566171045717 Marionette DEBUG Resetting recommended pref browser.download.panel.shown
[task 2019-08-18T23:30:45.728Z] 23:30:45 INFO - PID 26065 | 1566171045718 Marionette DEBUG Resetting recommended pref browser.newtabpage.enabled
[task 2019-08-18T23:30:45.729Z] 23:30:45 INFO - PID 26065 | 1566171045718 Marionette DEBUG Resetting recommended pref browser.pagethumbnails.capturing_disabled
[task 2019-08-18T23:30:45.731Z] 23:30:45 INFO - PID 26065 | 1566171045718 Marionette DEBUG Resetting recommended pref browser.search.update
[task 2019-08-18T23:30:45.731Z] 23:30:45 INFO - PID 26065 | 1566171045718 Marionette DEBUG Resetting recommended pref browser.tabs.disableBackgroundZombification
[task 2019-08-18T23:30:45.733Z] 23:30:45 INFO - PID 26065 | 1566171045718 Marionette DEBUG Resetting recommended pref browser.tabs.remote.separatePrivilegedContentProcess
[task 2019-08-18T23:30:45.734Z] 23:30:45 INFO - PID 26065 | 1566171045718 Marionette DEBUG Resetting recommended pref browser.tabs.unloadOnLowMemory
[task 2019-08-18T23:30:45.735Z] 23:30:45 INFO - PID 26065 | 1566171045719 Marionette DEBUG Resetting recommended pref browser.tabs.warnOnCloseOtherTabs
[task 2019-08-18T23:30:45.736Z] 23:30:45 INFO - PID 26065 | 1566171045719 Marionette DEBUG Resetting recommended pref browser.tabs.warnOnOpen
[task 2019-08-18T23:30:45.737Z] 23:30:45 INFO - PID 26065 | 1566171045719 Marionette DEBUG Resetting recommended pref browser.usedOnWindows10.introURL
[task 2019-08-18T23:30:45.738Z] 23:30:45 INFO - PID 26065 | 1566171045719 Marionette DEBUG Resetting recommended pref browser.urlbar.suggest.searches
[task 2019-08-18T23:30:45.739Z] 23:30:45 INFO - PID 26065 | 1566171045719 Marionette DEBUG Resetting recommended pref datareporting.policy.dataSubmissionPolicyAccepted
[task 2019-08-18T23:30:45.741Z] 23:30:45 INFO - PID 26065 | 1566171045719 Marionette DEBUG Resetting recommended pref dom.disable_beforeunload
[task 2019-08-18T23:30:45.741Z] 23:30:45 INFO - PID 26065 | 1566171045719 Marionette DEBUG Resetting recommended pref dom.disable_open_during_load
[task 2019-08-18T23:30:45.742Z] 23:30:45 INFO - PID 26065 | 1566171045720 Marionette DEBUG Resetting recommended pref dom.file.createInChild
[task 2019-08-18T23:30:45.744Z] 23:30:45 INFO - PID 26065 | 1566171045720 Marionette DEBUG Resetting recommended pref dom.max_chrome_script_run_time
[task 2019-08-18T23:30:45.744Z] 23:30:45 INFO - PID 26065 | 1566171045720 Marionette DEBUG Resetting recommended pref dom.max_script_run_time
[task 2019-08-18T23:30:45.745Z] 23:30:45 INFO - PID 26065 | 1566171045720 Marionette DEBUG Resetting recommended pref dom.push.connection.enabled
[task 2019-08-18T23:30:45.747Z] 23:30:45 INFO - PID 26065 | 1566171045721 Marionette DEBUG Resetting recommended pref extensions.getAddons.cache.enabled
[task 2019-08-18T23:30:45.748Z] 23:30:45 INFO - PID 26065 | 1566171045721 Marionette DEBUG Resetting recommended pref extensions.webservice.discoverURL
[task 2019-08-18T23:30:45.749Z] 23:30:45 INFO - PID 26065 | 1566171045721 Marionette DEBUG Resetting recommended pref network.http.prompt-temp-redirect
[task 2019-08-18T23:30:45.749Z] 23:30:45 INFO - PID 26065 | 1566171045721 Marionette DEBUG Resetting recommended pref network.http.speculative-parallel-limit
[task 2019-08-18T23:30:45.751Z] 23:30:45 INFO - PID 26065 | 1566171045722 Marionette DEBUG Resetting recommended pref privacy.trackingprotection.enabled
[task 2019-08-18T23:30:45.752Z] 23:30:45 INFO - PID 26065 | 1566171045723 Marionette DEBUG Resetting recommended pref security.fileuri.strict_origin_policy
[task 2019-08-18T23:30:45.752Z] 23:30:45 INFO - PID 26065 | 1566171045724 Marionette DEBUG Resetting recommended pref security.notification_enable_delay
[task 2019-08-18T23:30:45.754Z] 23:30:45 INFO - PID 26065 | 1566171045724 Marionette DEBUG Resetting recommended pref signon.autofillForms
[task 2019-08-18T23:30:45.755Z] 23:30:45 INFO - PID 26065 | 1566171045725 Marionette DEBUG Resetting recommended pref signon.rememberSignons
[task 2019-08-18T23:30:45.756Z] 23:30:45 INFO - PID 26065 | 1566171045725 Marionette DEBUG Resetting recommended pref toolkit.cosmeticAnimations.enabled
[task 2019-08-18T23:30:45.756Z] 23:30:45 INFO - PID 26065 | 1566171045726 Marionette DEBUG Remote service is inactive
[task 2019-08-18T23:30:46.196Z] 23:30:46 INFO - PID 26065 | 1566171046189 geckodriver::marionette DEBUG Browser process stopped: exit code: 0
[task 2019-08-18T23:30:46.200Z] 23:30:46 INFO - PID 26065 | 1566171046194 webdriver::server DEBUG <- 200 OK {"value":null}
[task 2019-08-18T23:30:46.201Z] 23:30:46 INFO - STDOUT: tests/web-platform/tests/webdriver/tests/new_session/timeouts.py::test_invalid_timeouts[timeouts0]
[task 2019-08-18T23:30:46.209Z] 23:30:46 INFO - TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/new_session/timeouts.py | expected OK
[task 2019-08-18T23:30:46.209Z] 23:30:46 INFO - TEST-INFO took 30008ms
[task 2019-08-18T23:30:46.274Z] 23:30:46 INFO - STDOUT: PASSED
[task 2019-08-18T23:30:46.275Z] 23:30:46 INFO - STDOUT: tests/web-platform/tests/webdriver/tests/new_session/timeouts.py::test_invalid_timeouts[timeouts1]
[task 2019-08-18T23:30:46.278Z] 23:30:46 INFO - PID 26065 | 1566171046198 webdriver::server DEBUG -> POST /session {"capabilities": {"alwaysMatch": {"timeouts": {"pageLoad": 300000, "implicit": null, "script": 30000}, "moz:firefoxOptions": {"binary": "/builds/worker/workspace/build/application/firefox/firefox", "prefs": {"network.process.enabled": false, "media.peerconnection.mtransport_process": false, "layers.d3d11.enable-blacklist": false, "network.dns.localDomains": "www1.xn--n8j6ds53lwwkrqhv28a.web-platform.test,xn--lve-6lad.www1.web-platform.test,www.www2.not-web-platform.test,www2.www2.not-web-platform.test,xn--lve-6lad.www.not-web-platform.test,xn--n8j6ds53lwwkrqhv28a.not-web-platform.test,www.not-web-platform.test,xn--n8j6ds53lwwkrqhv28a.www.not-web-platform.test,not-web-platform.test,www1.www.not-web-platform.test,xn--n8j6ds53lwwkrqhv28a.www1.web-platform.test,www2.not-web-platform.test,www1.not-web-platform.test,www1.www1.web-platform.test,www2.xn--lve-6lad.web-platform.test,www1.xn--n8j6ds53lwwkrqhv28a.not-web-platform.test,xn--n8j6ds53lwwkrqhv28a.xn--n8j6ds53lwwkrqhv28a.web-platform.test,www1.www2.web-platform.test,xn--lve-6lad.xn--n8j6ds53lwwkrqhv28a.not-web-platform.test,xn--lve-6lad.xn--lve-6lad.not-web-platform.test,www2.www1.not-web-platform.test,www2.xn--n8j6ds53lwwkrqhv28a.web-platform.test,www.xn--n8j6ds53lwwkrqhv28a.not-web-platform.test,web-platform.test,xn--n8j6ds53lwwkrqhv28a.xn--lve-6lad.not-web-platform.test,xn--lve-6lad.www.web-platform.test,www.www.web-platform.test,www1.xn--lve-6lad.web-platform.test,xn--lve-6lad.www2.web-platform.test,www.www2.web-platform.test,www2.www.web-platform.test,xn--n8j6ds53lwwkrqhv28a.www2.not-web-platform.test,www1.www.web-platform.test,www.xn--lve-6lad.web-platform.test,www.www.not-web-platform.test,xn--lve-6lad.xn--lve-6lad.web-platform.test,xn--lve-6lad.www1.not-web-platform.test,www1.www1.not-web-platform.test,xn--n8j6ds53lwwkrqhv28a.xn--n8j6ds53lwwkrqhv28a.not-web-platform.test,xn--n8j6ds53lwwkrqhv28a.www2.web-platform.test,xn--n8j6ds53lwwkrqhv28a.www1.not-web-platform.test,www2.www2.web-platform.test,xn--lve-6lad.web-platform.test,xn--n8j6ds53lwwkrqhv28a.web-platform.test,xn--n8j6ds53lwwkrqhv28a.www.web-platform.test,xn--lve-6lad.not-web-platform.test,www2.xn--n8j6ds53lwwkrqhv28a.not-web-platform.test,www2.xn--lve-6lad.not-web-platform.test,xn--n8j6ds53lwwkrqhv28a.xn--lve-6lad.web-platform.test,www1.xn--lve-6lad.not-web-platform.test,www1.web-platform.test,www.www1.web-platform.test,www2.web-platform.test,www.xn--lve-6lad.not-web-platform.test,www.web-platform.test,xn--lve-6lad.xn--n8j6ds53lwwkrqhv28a.web-platform.test,www1.www2.not-web-platform.test,www2.www1.web-platform.test,www.www1.not-web-platform.test,www.xn--n8j6ds53lwwkrqhv28a.web-platform.test,xn--lve-6lad.www2.not-web-platform.test,www2.www.not-web-platform.test"}}}}}
[task 2019-08-18T23:30:46.279Z] 23:30:46 INFO - PID 26065 | 1566171046199 webdriver::server DEBUG <- 400 Bad Request {"value":{"error":"invalid argument","message":"implicit timeouts value is not a number: null","stacktrace":""}}
[task 2019-08-18T23:30:46.279Z] 23:30:46 INFO - STDOUT: PASSED
[task 2019-08-18T23:30:46.279Z] 23:30:46 INFO - STDOUT: tests/web-platform/tests/webdriver/tests/new_session/timeouts.py::test_invalid_timeouts[timeouts2]
[task 2019-08-18T23:30:46.283Z] 23:30:46 INFO - PID 26065 | 1566171046205 webdriver::server DEBUG -> POST /session {"capabilities": {"alwaysMatch": {"timeouts": {"pageLoad": null, "implicit": 0, "script": 30000}, "moz:firefoxOptions": {"binary": "/builds/worker/workspace/build/application/firefox/firefox", "prefs": {"network.process.enabled": false, "media.peerconnection.mtransport_process": false, "layers.d3d11.enable-blacklist": false, "network.dns.localDomains": "www1.xn--n8j6ds53lwwkrqhv28a.web-platform.test,xn--lve-6lad.www1.web-platform.test,www.www2.not-web-platform.test,www2.www2.not-web-platform.test,xn--lve-6lad.www.not-web-platform.test,xn--n8j6ds53lwwkrqhv28a.not-web-platform.test,www.not-web-platform.test,xn--n8j6ds53lwwkrqhv28a.www.not-web-platform.test,not-web-platform.test,www1.www.not-web-platform.test,xn--n8j6ds53lwwkrqhv28a.www1.web-platform.test,www2.not-web-platform.test,www1.not-web-platform.test,www1.www1.web-platform.test,www2.xn--lve-6lad.web-platform.test,www1.xn--n8j6ds53lwwkrqhv28a.not-web-platform.test,xn--n8j6ds53lwwkrqhv28a.xn--n8j6ds53lwwkrqhv28a.web-platform.test,www1.www2.web-platform.test,xn--lve-6lad.xn--n8j6ds53lwwkrqhv28a.not-web-platform.test,xn--lve-6lad.xn--lve-6lad.not-web-platform.test,www2.www1.not-web-platform.test,www2.xn--n8j6ds53lwwkrqhv28a.web-platform.test,www.xn--n8j6ds53lwwkrqhv28a.not-web-platform.test,web-platform.test,xn--n8j6ds53lwwkrqhv28a.xn--lve-6lad.not-web-platform.test,xn--lve-6lad.www.web-platform.test,www.www.web-platform.test,www1.xn--lve-6lad.web-platform.test,xn--lve-6lad.www2.web-platform.test,www.www2.web-platform.test,www2.www.web-platform.test,xn--n8j6ds53lwwkrqhv28a.www2.not-web-platform.test,www1.www.web-platform.test,www.xn--lve-6lad.web-platform.test,www.www.not-web-platform.test,xn--lve-6lad.xn--lve-6lad.web-platform.test,xn--lve-6lad.www1.not-web-platform.test,www1.www1.not-web-platform.test,xn--n8j6ds53lwwkrqhv28a.xn--n8j6ds53lwwkrqhv28a.not-web-platform.test,xn--n8j6ds53lwwkrqhv28a.www2.web-platform.test,xn--n8j6ds53lwwkrqhv28a.www1.not-web-platform.test,www2.www2.web-platform.test,xn--lve-6lad.web-platform.test,xn--n8j6ds53lwwkrqhv28a.web-platform.test,xn--n8j6ds53lwwkrqhv28a.www.web-platform.test,xn--lve-6lad.not-web-platform.test,www2.xn--n8j6ds53lwwkrqhv28a.not-web-platform.test,www2.xn--lve-6lad.not-web-platform.test,xn--n8j6ds53lwwkrqhv28a.xn--lve-6lad.web-platform.test,www1.xn--lve-6lad.not-web-platform.test,www1.web-platform.test,www.www1.web-platform.test,www2.web-platform.test,www.xn--lve-6lad.not-web-platform.test,www.web-platform.test,xn--lve-6lad.xn--n8j6ds53lwwkrqhv28a.web-platform.test,www1.www2.not-web-platform.test,www2.www1.web-platform.test,www.www1.not-web-platform.test,www.xn--n8j6ds53lwwkrqhv28a.web-platform.test,xn--lve-6lad.www2.not-web-platform.test,www2.www.not-web-platform.test"}}}}}
[task 2019-08-18T23:30:46.283Z] 23:30:46 INFO - PID 26065 | 1566171046206 webdriver::server DEBUG <- 400 Bad Request {"value":{"error":"invalid argument","message":"pageLoad timeouts value is not a number: null","stacktrace":""}}
[task 2019-08-18T23:30:46.283Z] 23:30:46 INFO - Closing logging queue
[task 2019-08-18T23:30:46.284Z] 23:30:46 INFO - queue closed
[task 2019-08-18T23:30:46.284Z] 23:30:46 INFO - Starting runner
[task 2019-08-18T23:30:46.297Z] 23:30:46 INFO - WebDriver HTTP server listening at http://127.0.0.1:

See Also: → 1495002

I can see some delayed marionette-startup-requested notifications, which actually add a significant amount of extra time due to multiple restarts of the browser. Which means the allowed 30s wouldn't be enough. Lets observe how often this failure happens over the next week.

[task 2019-08-18T23:30:32.560Z] 23:30:32 INFO - PID 26065 | 1566171032551 Marionette TRACE Received observer notification toplevel-window-ready
[task 2019-08-18T23:30:35.463Z] 23:30:35 INFO - PID 26065 | 1566171035455 Marionette TRACE Received observer notification marionette-startup-requested

I think the best bet here is to extend the timeout of the test given that it restarts the browser 7 times. With a default timeout of 25s it would give each test including startup and shutdown of Firefox about 3 seconds.

I know that there might be a regression in start-up time from a week ago, but not sure if Marionette helps us to really get this investigated. Andreas, what do you think?

Also CC'ing Florian in case he is aware of some recent startup regressions.

Blocks: 1495002

Maybe we should just get this startup regression investigated. Vicky, while Florian is on PTO is there someone else who could help with that? Please see my comment 1.

As the intermittent view shows this is Linux64 only. It affects debug, but also opt builds, and started on August 12th. The first affected commit an central was this merge:

https://treeherder.mozilla.org/#/jobs?repo=mozilla-central&selectedJob=261237340&revision=076dd880cd6728ebcc021f8ebcf82ce0f515d8d0

There is one patch for Marionette (bug 1572687) which disables the GFX sanity window by setting the preference sanity-test.running to true, but could that cause a delay of 3 seconds for opt builds? Matt, do you have an idea?

Flags: needinfo?(vchin)
Flags: needinfo?(matt.woodrow)
OS: Unspecified → Linux
Hardware: Unspecified → x86_64

sanity-test.running is the internal preference the sanity test uses to mark when it's running. If you set it to true, then the sanity test will think we must have crashed during a previous run, and so it'll disable HW accelerated video and record telemetry.

I don't think that really explains a 3 second hang, but possibly?

Adding a new pref to just turn it off would be preferable.

Flags: needinfo?(matt.woodrow)

Ok, I would suggest to backout the patch from bug 1572687 to see if this has been caused the start-up regression, and then get it implemented properly with a new flag.

Matt, which name for the preference would you suggest? Would sanity-test.disabled be fine?

Flags: needinfo?(matt.woodrow)

Sounds good to me!

Flags: needinfo?(matt.woodrow)
Flags: needinfo?(vchin) → needinfo?(mconley)

(In reply to Henrik Skupin (:whimboo) [⌚️UTC+2] from comment #7)

Ok, I would suggest to backout the patch from bug 1572687 to see if this has been caused the start-up regression, and then get it implemented properly with a new flag.

Matt, which name for the preference would you suggest? Would sanity-test.disabled be fine?

Hey whimboo, did this experiment take place? Do we know if the sanity test is the culprit here?

Flags: needinfo?(mconley) → needinfo?(hskupin)

No, it's mostly not. Even with the backout of the patch those timeout errors are still present. Maybe it's related to bug 1577713, which actually shows up to 20s of delay!

Mike, if you have an idea for the other bug please let us know. Maybe just reply to the other bug, which I will mark as dependency now.

No longer blocks: 1495002
Depends on: 1577713
Flags: needinfo?(hskupin) → needinfo?(mconley)

Moving needinfo to bug 1577713.

Flags: needinfo?(mconley)

There are still failures present. So the patch to disable the GFX sanity windows hasn't caused this regression.

In the last 7 days, there have been 31 failures on linux64-ccov platform, debug build type.

An example of a recent log file:
https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=272091988&repo=mozilla-central&lineNumber=67116

And the relevant part of the log:
[task 2019-10-20T23:48:48.279Z] 23:48:48 INFO - PID 9248 | [CodeCoverage] Setting handlers for process 20503.
[task 2019-10-20T23:48:48.449Z] 23:48:48 INFO - PID 9248 | ++DOCSHELL 0x7fbc291ba000 == 1 [pid = 20503] [id = {deab4cd3-0263-44b1-aaf4-b56461bd82dd}]
[task 2019-10-20T23:48:48.511Z] 23:48:48 INFO - PID 9248 | ++DOMWINDOW == 1 (0x7fbc2a5bd2e0) [pid = 20503] [serial = 1] [outer = (nil)]
[task 2019-10-20T23:48:48.514Z] 23:48:48 INFO - PID 9248 | ++DOMWINDOW == 2 (0x7fbc29015c00) [pid = 20503] [serial = 2] [outer = 0x7fbc2a5bd2e0]
[task 2019-10-20T23:48:48.551Z] 23:48:48 INFO - PID 9248 | [Child 20503, Main Thread] WARNING: Fallback to BasicLayerManager: file /builds/worker/workspace/build/src/dom/ipc/BrowserChild.cpp, line 2687
[task 2019-10-20T23:48:48.592Z] 23:48:48 INFO - PID 9248 | ++DOCSHELL 0x7fbc29b21800 == 2 [pid = 20503] [id = {c360b847-988a-4e6a-9590-a3e7b5f7c825}]
[task 2019-10-20T23:48:48.594Z] 23:48:48 INFO - PID 9248 | ++DOMWINDOW == 3 (0x7fbc2a5bd4c0) [pid = 20503] [serial = 3] [outer = (nil)]
[task 2019-10-20T23:48:48.595Z] 23:48:48 INFO - PID 9248 | ++DOMWINDOW == 4 (0x7fbc2916e400) [pid = 20503] [serial = 4] [outer = 0x7fbc2a5bd4c0]
[task 2019-10-20T23:48:48.611Z] 23:48:48 INFO - PID 9248 | [Child 20503, Main Thread] WARNING: Fallback to BasicLayerManager: file /builds/worker/workspace/build/src/dom/ipc/BrowserChild.cpp, line 2687
[task 2019-10-20T23:48:48.628Z] 23:48:48 INFO - PID 9248 | ++DOCSHELL 0x7fbc2a665000 == 3 [pid = 20503] [id = {0693674d-ab28-4212-9ee1-03673fdf259a}]
[task 2019-10-20T23:48:48.629Z] 23:48:48 INFO - PID 9248 | ++DOMWINDOW == 5 (0x7fbc2a5bc200) [pid = 20503] [serial = 5] [outer = (nil)]
[task 2019-10-20T23:48:48.630Z] 23:48:48 INFO - PID 9248 | ++DOMWINDOW == 6 (0x7fbc29170800) [pid = 20503] [serial = 6] [outer = 0x7fbc2a5bc200]
[task 2019-10-20T23:48:48.646Z] 23:48:48 INFO - PID 9248 | [Child 20503, Main Thread] WARNING: Fallback to BasicLayerManager: file /builds/worker/workspace/build/src/dom/ipc/BrowserChild.cpp, line 2687
[task 2019-10-20T23:48:48.663Z] 23:48:48 INFO - PID 9248 | ++DOCSHELL 0x7fbc2a668000 == 4 [pid = 20503] [id = {38037f40-4597-4dd5-b1ab-8f2924790ed1}]
[task 2019-10-20T23:48:48.663Z] 23:48:48 INFO - PID 9248 | ++DOMWINDOW == 7 (0x7fbc2a5bd6a0) [pid = 20503] [serial = 7] [outer = (nil)]
[task 2019-10-20T23:48:48.664Z] 23:48:48 INFO - PID 9248 | ++DOMWINDOW == 8 (0x7fbc29172c00) [pid = 20503] [serial = 8] [outer = 0x7fbc2a5bd6a0]
[task 2019-10-20T23:48:48.681Z] 23:48:48 INFO - PID 9248 | [Child 20503, Main Thread] WARNING: Fallback to BasicLayerManager: file /builds/worker/workspace/build/src/dom/ipc/BrowserChild.cpp, line 2687
[task 2019-10-20T23:48:48.881Z] 23:48:48 INFO - PID 9248 | ++DOMWINDOW == 9 (0x7fbc29179400) [pid = 20503] [serial = 9] [outer = 0x7fbc2a5bd2e0]
[task 2019-10-20T23:48:48.909Z] 23:48:48 INFO - PID 9248 | ++DOMWINDOW == 10 (0x7fbc2917b800) [pid = 20503] [serial = 10] [outer = 0x7fbc2a5bd4c0]
[task 2019-10-20T23:48:48.930Z] 23:48:48 INFO - PID 9248 | ++DOMWINDOW == 11 (0x7fbc2a54a800) [pid = 20503] [serial = 11] [outer = 0x7fbc2a5bc200]
[task 2019-10-20T23:48:48.956Z] 23:48:48 INFO - PID 9248 | ++DOMWINDOW == 12 (0x7fbc29badc00) [pid = 20503] [serial = 12] [outer = 0x7fbc2a5bd6a0]
[task 2019-10-20T23:48:49.261Z] 23:48:49 INFO - PID 9248 | [Child 20532, Main Thread] WARNING: No CID found when attempting to map contract ID: file /builds/worker/workspace/build/src/xpcom/components/nsComponentManager.cpp, line 732
[task 2019-10-20T23:48:49.714Z] 23:48:49 INFO - PID 9248 | Couldn't convert chrome URL: chrome://branding/locale/brand.properties
[task 2019-10-20T23:48:49.716Z] 23:48:49 INFO - PID 9248 | [CodeCoverage] Setting handlers for process 20532.
[task 2019-10-20T23:48:49.753Z] 23:48:49 INFO - PID 9248 | ++DOMWINDOW == 7 (0x7fab50db3800) [pid = 20454] [serial = 7] [outer = 0x7fab5a89ce20]
[task 2019-10-20T23:48:49.891Z] 23:48:49 INFO - PID 9248 | ++DOCSHELL 0x7ff0324b5000 == 1 [pid = 20532] [id = {567fda86-961c-475f-a7a4-3e7ba967d5a0}]
[task 2019-10-20T23:48:49.968Z] 23:48:49 INFO - PID 9248 | ++DOMWINDOW == 1 (0x7ff0337f3f20) [pid = 20532] [serial = 1] [outer = (nil)]
[task 2019-10-20T23:48:49.969Z] 23:48:49 INFO - PID 9248 | ++DOMWINDOW == 2 (0x7ff03378d800) [pid = 20532] [serial = 2] [outer = 0x7ff0337f3f20]
[task 2019-10-20T23:48:50.395Z] 23:48:50 INFO - PID 9248 | ++DOCSHELL 0x7fab50c79800 == 4 [pid = 20454] [id = {708a7102-15c7-4eca-abe9-01060886d79c}]
[task 2019-10-20T23:48:50.396Z] 23:48:50 INFO - PID 9248 | ++DOMWINDOW == 8 (0x7fab4f496020) [pid = 20454] [serial = 8] [outer = (nil)]
[task 2019-10-20T23:48:50.397Z] 23:48:50 INFO - PID 9248 | ++DOMWINDOW == 9 (0x7fab4f40bc00) [pid = 20454] [serial = 9] [outer = 0x7fab4f496020]
[task 2019-10-20T23:48:50.474Z] 23:48:50 INFO - PID 9248 | ++DOMWINDOW == 3 (0x7ff032483400) [pid = 20532] [serial = 3] [outer = 0x7ff0337f3f20]
[task 2019-10-20T23:48:50.939Z] 23:48:50 INFO - PID 9248 | [Parent 20454, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005: file /builds/worker/workspace/build/src/netwerk/cache/nsCacheService.cpp, line 173
[task 2019-10-20T23:48:51.190Z] 23:48:51 INFO - PID 9248 | [Parent 20454, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005: file /builds/worker/workspace/build/src/dom/base/ThirdPartyUtil.cpp, line 391
[task 2019-10-20T23:48:51.191Z] 23:48:51 INFO - PID 9248 | ++DOMWINDOW == 10 (0x7fab4dede000) [pid = 20454] [serial = 10] [outer = 0x7fab4f496020]
[task 2019-10-20T23:48:51.403Z] 23:48:51 INFO - PID 9248 | [Parent 20454, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005: file /builds/worker/workspace/build/src/dom/base/ThirdPartyUtil.cpp, line 391
[task 2019-10-20T23:48:51.403Z] 23:48:51 INFO - PID 9248 | [Parent 20454, Main Thread] WARNING: Failed to retarget HTML data delivery to the parser thread.: file /builds/worker/workspace/build/src/parser/html/nsHtml5StreamParser.cpp, line 1142
[task 2019-10-20T23:48:52.121Z] 23:48:52 INFO - PID 9248 | [Parent 20454, Main Thread] WARNING: Failed to get base domain!: file /builds/worker/workspace/build/src/ipc/glue/BackgroundUtils.cpp, line 364
[task 2019-10-20T23:48:53.016Z] 23:48:53 INFO - PID 9248 | [Parent 20454, Main Thread] WARNING: Suboptimal indexes for the SQL statement 0x7fab4d4f0970 (http://mzl.la/1FuID0j).: file /builds/worker/workspace/build/src/storage/mozStoragePrivateHelpers.cpp, line 108
[task 2019-10-20T23:48:53.220Z] 23:48:53 INFO - TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/new_session/timeouts.py | expected OK
[task 2019-10-20T23:48:53.220Z] 23:48:53 INFO - TEST-INFO took 105006ms
[task 2019-10-20T23:48:53.290Z] 23:48:53 INFO - STDOUT: FAILED
[task 2019-10-20T23:48:53.290Z] 23:48:53 INFO - STDOUT: tests/web-platform/tests/webdriver/tests/new_session/timeouts.py::test_invalid_timeouts[timeouts0]
[task 2019-10-20T23:48:53.291Z] 23:48:53 INFO - Closing logging queue
[task 2019-10-20T23:48:53.292Z] 23:48:53 INFO - queue closed
[task 2019-10-20T23:48:53.292Z] 23:48:53 INFO - Starting runner
[task 2019-10-20T23:48:53.321Z] 23:48:53 INFO - PID 20582 | 1571615333315 geckodriver DEBUG Listening on 127.0.0.1:59541
[task 2019-10-20T23:48:53.814Z] 23:48:53 INFO - WebDriver HTTP server listening at http://127.0.0.1:59541/

This is failing intermittent with https://bugzilla.mozilla.org/show_bug.cgi?id=1418778
Failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=272238404&repo=mozilla-central&lineNumber=52231

Henrik, as you are the triage owner of this component, could you please take a look at this?
Thank you!

Flags: needinfo?(hskupin)
Whiteboard: [stockwell needswork:owner]
Status: NEW → RESOLVED
Closed: 5 years ago
Flags: needinfo?(hskupin)
Resolution: --- → DUPLICATE

For the March 9th regression please use bug 1623007 for classification.

(In reply to Intermittent Failures Robot from comment #31)

Repository breakdown:

  • mozilla-release: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1574837&startday=2020-04-06&endday=2020-04-12&tree=all

Both failures have been wrongly classified and should have been bug 1623007.

Flags: needinfo?(apavel)

(In reply to Henrik Skupin (:whimboo) [⌚️UTC+2] from comment #32)

(In reply to Intermittent Failures Robot from comment #31)

Repository breakdown:

  • mozilla-release: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1574837&startday=2020-04-06&endday=2020-04-12&tree=all

Both failures have been wrongly classified and should have been bug 1623007.

I corrected those, sorry about that.

Flags: needinfo?(apavel)
Status: REOPENED → RESOLVED
Closed: 5 years ago4 years ago
Resolution: --- → INCOMPLETE
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.