Perma Mn2 win11 webrender [taskcluster:error] task aborted - max run time exceeded when Gecko 132 merges to beta on 2024-09-30
Categories
(Testing :: Marionette Client and Harness, defect, P1)
Tracking
(firefox-esr115 unaffected, firefox-esr128 unaffected, firefox131 unaffected, firefox132+ fixed, firefox133+ fixed)
| Tracking | Status | |
|---|---|---|
| firefox-esr115 | --- | unaffected |
| firefox-esr128 | --- | unaffected |
| firefox131 | --- | unaffected |
| firefox132 | + | fixed |
| firefox133 | + | fixed |
People
(Reporter: noemi_erli, Assigned: jmaher)
References
(Regression)
Details
(Keywords: regression)
Central-as-beta simulation:
How to run these simulations:
Failure log
[task 2024-09-29T13:06:41.374Z] 13:06:41 INFO - TEST-START | toolkit/xre/test/marionette/test_win32k_enrollment.py TestWin32kAutostart.test_37
[task 2024-09-29T13:06:41.377Z] 13:06:41 INFO - 1727615201377 Marionette DEBUG Closed connection 3
[task 2024-09-29T13:06:41.379Z] 13:06:41 INFO - 1727615201379 Marionette DEBUG Accepted connection 4 from 127.0.0.1:55061
[task 2024-09-29T13:06:41.384Z] 13:06:41 INFO - 1727615201383 Marionette DEBUG 4 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
[task 2024-09-29T13:06:41.386Z] 13:06:41 INFO - 1727615201386 Marionette DEBUG Waiting for initial application window
[task 2024-09-29T13:06:41.388Z] 13:06:41 INFO - 1727615201388 RemoteAgent TRACE [9] ProgressListener Start: expectNavigation=false resolveWhenStarted=false unloadTimeout=40000 waitForExplicitStart=false
[task 2024-09-29T13:06:41.388Z] 13:06:41 INFO - 1727615201388 RemoteAgent TRACE [9] ProgressListener Setting unload timer (40000ms)
[task 2024-09-29T13:06:41.389Z] 13:06:41 INFO - 1727615201388 RemoteAgent TRACE [9] Wait for initial navigation: isInitial=false, isLoadingDocument=false
[task 2024-09-29T13:06:41.389Z] 13:06:41 INFO - 1727615201388 RemoteAgent TRACE [9] Document already finished loading: about:blank
[task 2024-09-29T13:06:41.389Z] 13:06:41 INFO - 1727615201389 RemoteAgent TRACE [9] ProgressListener Stop: has error=false url=about:blank
[task 2024-09-29T13:06:41.391Z] 13:06:41 INFO - 1727615201392 Marionette DEBUG 4 <- [1,1,null,{"sessionId":"2e24a405-4ba8-4abf-8429-d5b4cd5c3742","capabilities":{"acceptInsecureCerts":false,"browserName":"firefox","browserVersion":"132.0","platformName":"windows","unhandledPromptBehavior":"dismiss and notify","userAgent":"Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:132.0) Gecko/20100101 Firefox/132.0","moz:buildID":"20240929110715","moz:headless":false,"moz:platformVersion":"10.0","moz:processID":1260,"moz:profile":"C:\\Users\\task_172761151884983\\AppData\\Local\\Temp\\tmprgghl1cl.mozrunner","moz:shutdownTimeout":300000,"pageLoadStrategy":"normal","timeouts":{"implicit":0,"pageLoad":300000,"script":30000},"setWindowRect":true,"strictFileInteractability":true,"moz:accessibilityChecks":false,"moz:webdriverClick":true,"moz:windowless":false,"proxy":{}}}]
[task 2024-09-29T13:06:41.400Z] 13:06:41 INFO - 1727615201400 Marionette DEBUG 4 -> [0,2,"WebDriver:SetTimeouts",{"script":30000}]
[task 2024-09-29T13:06:41.401Z] 13:06:41 INFO - 1727615201401 Marionette DEBUG 4 <- [1,2,null,{"value":null}]
[task 2024-09-29T13:06:41.407Z] 13:06:41 INFO - 1727615201407 Marionette DEBUG 4 -> [0,3,"WebDriver:SetTimeouts",{"pageLoad":300000}]
[task 2024-09-29T13:06:41.407Z] 13:06:41 INFO - 1727615201407 Marionette DEBUG 4 <- [1,3,null,{"value":null}]
[task 2024-09-29T13:06:41.408Z] 13:06:41 INFO - 1727615201409 Marionette DEBUG 4 -> [0,4,"WebDriver:SetTimeouts",{"implicit":0}]
[task 2024-09-29T13:06:41.408Z] 13:06:41 INFO - 1727615201410 Marionette DEBUG 4 <- [1,4,null,{"value":null}]
[task 2024-09-29T13:06:41.410Z] 13:06:41 INFO - 1727615201415 Marionette DEBUG 4 -> [0,5,"Marionette:SetContext",{"value":"chrome"}]
[task 2024-09-29T13:06:41.415Z] 13:06:41 INFO - 1727615201415 Marionette DEBUG 4 <- [1,5,null,{"value":null}]
[task 2024-09-29T13:06:41.416Z] 13:06:41 INFO - 1727615201419 Marionette DEBUG 4 -> [0,6,"Marionette:GetContext",{}]
[task 2024-09-29T13:06:41.420Z] 13:06:41 INFO - 1727615201419 Marionette DEBUG 4 <- [1,6,null,{"value":"chrome"}]
[task 2024-09-29T13:06:41.423Z] 13:06:41 INFO - 1727615201425 Marionette DEBUG 4 -> [0,7,"Marionette:SetContext",{"value":"chrome"}]
[task 2024-09-29T13:06:41.426Z] 13:06:41 INFO - 1727615201426 Marionette DEBUG 4 <- [1,7,null,{"value":null}]
[task 2024-09-29T13:06:41.431Z] 13:06:41 INFO - 1727615201435 Marionette DEBUG 4 -> [0,8,"WebDriver:ExecuteScript",{"script":"// We're running in a function, in a sandbox, that inherits from an\n // X-ray wrapped window. Anything we want to be globally available\n // needs to be defined on that window.\n window.env = Services.env;","args":[],"newSandbox":false,"sandbox":"win32k-autostart","line":49,"filename":"D:\\task_172761151884983\\build\\tests\\marionette\\tests\\toolkit\\xre\\test\\marionette\\test_win32k_enrollment.py"}]
[task 2024-09-29T13:06:41.455Z] 13:06:41 INFO - 1727615201461 RemoteAgent TRACE WebDriverProcessData actor created for PID 1260
[task 2024-09-29T13:06:41.467Z] 13:06:41 INFO - 1727615201466 Marionette TRACE [1] MarionetteCommands actor created for window id 2
[task 2024-09-29T13:06:41.478Z] 13:06:41 INFO - 1727615201482 Marionette DEBUG 4 <- [1,8,null,{"value":null}]
[task 2024-09-29T13:06:41.490Z] 13:06:41 INFO - 1727615201490 Marionette DEBUG 4 -> [0,9,"Marionette:SetContext",{"value":"chrome"}]
[task 2024-09-29T13:06:41.491Z] 13:06:41 INFO - 1727615201491 Marionette DEBUG 4 <- [1,9,null,{"value":null}]
[task 2024-09-29T13:06:41.495Z] 13:06:41 INFO - 1727615201495 Marionette DEBUG 4 -> [0,10,"Marionette:GetContext",{}]
[task 2024-09-29T13:06:41.496Z] 13:06:41 INFO - 1727615201496 Marionette DEBUG 4 <- [1,10,null,{"value":"chrome"}]
[task 2024-09-29T13:06:41.505Z] 13:06:41 INFO - 1727615201504 Marionette DEBUG 4 -> [0,11,"Marionette:SetContext",{"value":"chrome"}]
[task 2024-09-29T13:06:41.505Z] 13:06:41 INFO - 1727615201505 Marionette DEBUG 4 <- [1,11,null,{"value":null}]
[task 2024-09-29T13:06:41.511Z] 13:06:41 INFO - 1727615201511 Marionette DEBUG 4 -> [0,12,"WebDriver:ExecuteScript",{"script":"return Services.prefs.getBoolPref(\"security.sandbox.content.win32k-disable\");","args":[],"newSandbox":false,"sandbox":"win32k-autostart","line":49,"filename":"D:\\task_172761151884983\\build\\tests\\marionette\\tests\\toolkit\\xre\\test\\marionette\\test_win32k_enrollment.py"}]
[task 2024-09-29T13:06:41.514Z] 13:06:41 INFO - 1727615201515 Marionette DEBUG 4 <- [1,12,null,{"value":true}]
[task 2024-09-29T13:06:41.580Z] 13:06:41 INFO - 1727615201590 Marionette DEBUG 4 -> [0,13,"Marionette:SetContext",{"value":"chrome"}]
[task 2024-09-29T13:06:41.591Z] 13:06:41 INFO - 1727615201590 Marionette DEBUG 4 <- [1,13,null,{"value":null}]
[task 2024-09-29T13:06:41.594Z] 13:06:41 INFO - 1727615201594 Marionette DEBUG 4 -> [0,14,"Marionette:GetContext",{}]
[task 2024-09-29T13:06:41.595Z] 13:06:41 INFO - 1727615201594 Marionette DEBUG 4 <- [1,14,null,{"value":"chrome"}]
[task 2024-09-29T13:06:41.598Z] 13:06:41 INFO - 1727615201597 Marionette DEBUG 4 -> [0,15,"Marionette:SetContext",{"value":"chrome"}]
[task 2024-09-29T13:06:41.598Z] 13:06:41 INFO - 1727615201598 Marionette DEBUG 4 <- [1,15,null,{"value":null}]
[task 2024-09-29T13:06:41.627Z] 13:06:41 INFO - 1727615201633 Marionette DEBUG 4 -> [0,16,"WebDriver:ExecuteScript",{"script":"let win = Services.wm.getMostRecentWindow(\"navigator:browser\");\n let ses = \"security.sandbox.content.win32k-experime ... sandbox.content.win32k-disable\"),\n win32kStartupEnrollmentStatusPref: Services.prefs.getIntPref(ses),\n };","args":[],"newSandbox":false,"sandbox":"win32k-autostart","line":49,"filename":"D:\\task_172761151884983\\build\\tests\\marionette\\tests\\toolkit\\xre\\test\\marionette\\test_win32k_enrollment.py"}]
[task 2024-09-29T13:06:41.642Z] 13:06:41 INFO - 1727615201641 Marionette DEBUG 4 <- [1,16,null,{"value":{"win32kSessionStatus":15,"win32kStatus":15,"win32kExperimentStatus":0,"win32kPref":true,"win32kStartupEnrollmentStatusPref":0}}]
[task 2024-09-29T13:06:41.646Z] 13:06:41 INFO - 1727615201646 Marionette DEBUG 4 -> [0,17,"Marionette:SetContext",{"value":"chrome"}]
[task 2024-09-29T13:06:41.647Z] 13:06:41 INFO - 1727615201646 Marionette DEBUG 4 <- [1,17,null,{"value":null}]
[task 2024-09-29T13:06:41.651Z] 13:06:41 INFO - 1727615201650 Marionette DEBUG 4 -> [0,18,"Marionette:GetContext",{}]
[task 2024-09-29T13:06:41.651Z] 13:06:41 INFO - 1727615201650 Marionette DEBUG 4 <- [1,18,null,{"value":"chrome"}]
[task 2024-09-29T13:06:41.652Z] 13:06:41 INFO - 1727615201652 Marionette DEBUG 4 -> [0,19,"WebDriver:DeleteSession",{}]
[task 2024-09-29T13:06:41.653Z] 13:06:41 INFO - 1727615201653 Marionette TRACE [1] MarionetteCommands actor destroyed for window id 2
[task 2024-09-29T13:06:41.656Z] 13:06:41 INFO - 1727615201656 Marionette DEBUG 4 <- [1,19,null,{"value":null}]
[task 2024-09-29T13:06:41.845Z] 13:06:41 INFO - Application command: D:\task_172761151884983\build\application\firefox\firefox.exe -marionette --wait-for-browser -profile C:\Users\task_172761151884983\AppData\Local\Temp\tmpiifh_d1w.mozrunner
[task 2024-09-29T13:06:43.597Z] 13:06:43 INFO - 1727615203600 Marionette INFO Marionette enabled
[task 2024-09-29T13:06:43.612Z] 13:06:43 INFO - 1727615203614 Marionette TRACE Received observer notification final-ui-startup
[task 2024-09-29T13:06:44.457Z] 13:06:44 INFO - 1727615204465 Marionette INFO Listening on port 2828
[task 2024-09-29T13:06:44.473Z] 13:06:44 INFO - 1727615204472 Marionette DEBUG Marionette is listening
[task 2024-09-29T13:06:44.535Z] 13:06:44 INFO - 1727615204535 Marionette DEBUG Accepted connection 0 from 127.0.0.1:55067
[task 2024-09-29T13:06:44.598Z] 13:06:44 INFO - 1727615204612 Marionette DEBUG Closed connection 0
[task 2024-09-29T13:06:44.723Z] 13:06:44 INFO - 1727615204736 Marionette DEBUG Accepted connection 1 from 127.0.0.1:55068
[task 2024-09-29T13:06:45.334Z] 13:06:45 INFO - 1727615205334 Marionette DEBUG Closed connection 1
[task 2024-09-29T13:06:45.366Z] 13:06:45 INFO - 1727615205371 Marionette DEBUG Accepted connection 2 from 127.0.0.1:55069
[task 2024-09-29T13:06:45.413Z] 13:06:45 INFO - 1727615205413 Marionette DEBUG Closed connection 2
[task 2024-09-29T13:06:45.415Z] 13:06:45 INFO - 1727615205414 Marionette DEBUG Accepted connection 3 from 127.0.0.1:55070
[task 2024-09-29T13:06:45.757Z] 13:06:45 INFO - 1727615205770 Marionette DEBUG 3 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
[task 2024-09-29T13:06:45.789Z] 13:06:45 INFO - 1727615205795 Marionette DEBUG Waiting for initial application window
[taskcluster:error] Aborting task...
[taskcluster 2024-09-29T13:06:51.756Z] SUCCESS: The process with PID 1920 (child process of PID 3032) has been terminated.
[taskcluster 2024-09-29T13:06:51.756Z] SUCCESS: The process with PID 10168 (child process of PID 3032) has been terminated.
[taskcluster 2024-09-29T13:06:51.756Z] SUCCESS: The process with PID 2200 (child process of PID 3032) has been terminated.
[taskcluster 2024-09-29T13:06:51.756Z] SUCCESS: The process with PID 3032 (child process of PID 5328) has been terminated.
[taskcluster 2024-09-29T13:06:51.756Z] SUCCESS: The process with PID 8944 (child process of PID 10176) has been terminated.
[taskcluster 2024-09-29T13:06:51.756Z] SUCCESS: The process with PID 7040 (child process of PID 10176) has been terminated.
[taskcluster 2024-09-29T13:06:51.756Z] SUCCESS: The process with PID 5328 (child process of PID 10176) has been terminated.
[taskcluster 2024-09-29T13:06:51.756Z] SUCCESS: The process with PID 10176 (child process of PID 3268) has been terminated.
[taskcluster 2024-09-29T13:06:51.756Z] SUCCESS: The process with PID 2880 (child process of PID 9256) has been terminated.
[taskcluster 2024-09-29T13:06:51.756Z] SUCCESS: The process with PID 3268 (child process of PID 9256) has been terminated.
[taskcluster 2024-09-29T13:06:51.756Z] SUCCESS: The process with PID 9256 (child process of PID 6124) has been terminated.
[taskcluster 2024-09-29T13:06:51.756Z] SUCCESS: The process with PID 10148 (child process of PID 10048) has been terminated.
[taskcluster 2024-09-29T13:06:51.756Z] SUCCESS: The process with PID 6124 (child process of PID 10048) has been terminated.
[taskcluster 2024-09-29T13:06:51.756Z] SUCCESS: The process with PID 10048 (child process of PID 7080) has been terminated.
[taskcluster 2024-09-29T13:06:51.756Z]
[taskcluster 2024-09-29T13:06:51.756Z] === Task Finished ===
[taskcluster 2024-09-29T13:06:51.756Z] Task Duration: 1h0m0.1652838s
[taskcluster 2024-09-29T13:06:52.197Z] Uploading artifact public/test_info/report.html from file D:\task_172761151884983\build\blobber_upload_dir\report.html with content encoding "gzip", mime type "text/html; charset=utf-8" and expiry 2024-10-27T11:14:50.532Z
[taskcluster 2024-09-29T13:06:52.200Z] Uploading artifact public/logs/localconfig.json from file D:\task_172761151884983\logs\localconfig.json with content encoding "gzip", mime type "application/json" and expiry 2024-10-27T11:14:50.532Z
[taskcluster 2024-09-29T13:06:52.417Z] Uploading artifact public/test_info/marionette_errorsummary.log from file D:\task_172761151884983\build\blobber_upload_dir\marionette_errorsummary.log with content encoding "gzip", mime type "text/plain" and expiry 2024-10-27T11:14:50.532Z
[taskcluster 2024-09-29T13:06:52.632Z] Uploading link artifact public/logs/live.log to artifact public/logs/live_backing.log with expiry 2024-10-27T11:14:50.532Z
[taskcluster:error] task aborted - max run time exceeded
This started to fail on this run but was missed by the single tracking known bug.
Joel, could you please take a look at this issue?
|
Reporter | |
Updated•26 days ago
|
| Comment hidden (Intermittent Failures Robot) |
|
||
Comment 2•26 days ago
|
||
Maybe this is caused by the additional test that we weren't running before?
On Windows especially the profile related tests are running quite slow but that's not new. I filed bug 1921725 to investigate that.
|
Assignee | |
Comment 3•25 days ago
|
||
on central, the win/asan marionette chunks are both completed in 45 +- 3 minutes, but on this beta sim run it is 18 and 60 minute timeout.
on central we have:
93 test-start in chunk 1
997 test-start in chunk 2
on beta-sim we have:
35 test-start in chunk 1
1000+ test-start in chunk 2
some reason on beta-sim toolkit/xre/* is running in chunk2 when if run in chunk1 it would balance out.
central:
chunk2: ["browser/components/migration/tests/marionette/manifest.toml", "browser/components/search/test/marionette/manifest.toml", "browser/components/sessionstore/test/marionette/manifest.toml", "browser/components/tests/marionette/manifest.toml", "dom/indexedDB/test/marionette/manifest.toml", "dom/workers/test/marionette/manifest.toml", "js/xpconnect/tests/marionette/manifest.toml", "netwerk/test/marionette/manifest.toml", "toolkit/components/antitracking/bouncetrackingprotection/test/marionette/manifest.toml", "toolkit/components/extensions/test/marionette/manifest-serviceworker.toml", "toolkit/xre/test/marionette/manifest.toml"]
chunk1: ["browser/components/backup/tests/marionette/manifest.toml", "browser/components/places/tests/marionette/manifest.toml", "browser/components/search/test/marionette/telemetry/manifest.toml", "browser/components/sidebar/tests/marionette/manifest.toml", "dom/cache/test/marionette/manifest.toml", "dom/quota/test/marionette/manifest.toml", "extensions/pref/autoconfig/test/marionette/manifest.toml", "layout/base/tests/marionette/manifest.toml", "testing/marionette/harness/marionette_harness/tests/unit/unit-tests.toml", "toolkit/components/cleardata/tests/marionette/manifest.toml", "toolkit/modules/tests/marionette/manifest.toml", "toolkit/mozapps/update/tests/marionette/manifest.toml"]
beta-sim:
chunk1: ["browser/components/migration/tests/marionette/manifest.toml", "browser/components/search/test/marionette/manifest.toml", "browser/components/sessionstore/test/marionette/manifest.toml", "browser/components/tests/marionette/manifest.toml", "dom/indexedDB/test/marionette/manifest.toml", "dom/workers/test/marionette/manifest.toml", "js/xpconnect/tests/marionette/manifest.toml", "netwerk/test/marionette/manifest.toml", "toolkit/components/antitracking/bouncetrackingprotection/test/marionette/manifest.toml", "toolkit/modules/tests/marionette/manifest.toml"]
chunk2: ["browser/components/backup/tests/marionette/manifest.toml", "browser/components/places/tests/marionette/manifest.toml", "browser/components/search/test/marionette/telemetry/manifest.toml", "browser/components/sidebar/tests/marionette/manifest.toml", "dom/cache/test/marionette/manifest.toml", "dom/quota/test/marionette/manifest.toml", "extensions/pref/autoconfig/test/marionette/manifest.toml", "layout/base/tests/marionette/manifest.toml", "testing/marionette/harness/marionette_harness/tests/unit/unit-tests.toml", "toolkit/components/cleardata/tests/marionette/manifest.toml", "toolkit/xre/test/marionette/manifest.toml"]
|
|
Assignee | |
Comment 4•25 days ago
|
||
these extra manifests are run on m-c:
{'toolkit/mozapps/update/tests/marionette/manifest.toml', 'toolkit/components/extensions/test/marionette/manifest-serviceworker.toml'}
specifically: 'toolkit/components/extensions/test/marionette/manifest-serviceworker.toml', is a skip-if !nightly:
https://searchfox.org/mozilla-central/source/toolkit/components/extensions/test/marionette/manifest-serviceworker.toml
so somehow we need to figure out how to get these more balanced- one idea is splitting into 3 chunks for asan.
|
|
||
Comment 5•25 days ago
|
||
Should we actually do bug 1921411? This would get the real Marionette unit tests off those chunks. Given that the profile tests take 20min it could already free up the time?
|
|
||
Comment 6•25 days ago
|
||
But in the interim it might work to increase the total chunks. I assume it cannot be done per branch but we have just a single config?
|
|
Assignee | |
Comment 7•25 days ago
|
||
oh, good idea bug 1921411 could fix this and make more things balanced, I can give it a try.
|
||
Updated•25 days ago
|
|
|
||
Updated•25 days ago
|
|
|
||
Comment 8•24 days ago
|
||
The fix for bug 1921411 should be close for landing, so lets hope it fixes the perma failure for sure.
|
||
Comment 9•22 days ago
|
||
:jmaher, since you are the author of the regressor, bug 1916456, could you take a look? Also, could you set the severity field?
For more information, please visit BugBot documentation.
|
|
Assignee | |
Comment 10•22 days ago
|
||
waiting on final review in bug 1921411
| Comment hidden (Intermittent Failures Robot) |
|
||
Comment 12•16 days ago
|
||
Fixed by bug 1921411.
| Comment hidden (Intermittent Failures Robot) |
Description
•