Intermittent TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/new_session/timeouts.py | expected OK
Categories
(Remote Protocol :: Marionette, defect, P5)
Tracking
(firefox69 unaffected, firefox70 fix-optional, firefox71 fix-optional, firefox72 ?)
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:
Comment 1•5 years ago
|
||
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
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment 4•5 years ago
|
||
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.
Comment 5•5 years ago
|
||
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:
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?
Comment 6•5 years ago
|
||
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.
Comment 7•5 years ago
|
||
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?
Updated•5 years ago
|
Comment 9•5 years ago
|
||
(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?
Comment 10•5 years ago
|
||
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.
Comment hidden (Intermittent Failures Robot) |
Comment 13•5 years ago
|
||
There are still failures present. So the patch to disable the GFX sanity windows hasn't caused this regression.
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Updated•5 years ago
|
Comment 21•5 years ago
|
||
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!
Updated•5 years ago
|
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment 26•4 years ago
•
|
||
Recent failures show that this is not perma failing.
Also, ccov builds dont run anymore on beta, so there is no reason to keep this as a duplicate of Bug 1495002.
Comment 27•4 years ago
|
||
For the March 9th regression please use bug 1623007 for classification.
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment 32•4 years ago
|
||
(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.
Comment 33•4 years ago
|
||
(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=allBoth failures have been wrongly classified and should have been bug 1623007.
I corrected those, sorry about that.
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment 36•4 years ago
|
||
https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.
Comment 37•1 year ago
|
||
Moving bug to Remote Protocol::Marionette component per bug 1815831.
Description
•