Closed Bug 1921685 Opened 4 months ago Closed 4 months ago

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)

Product:
Testing
Component:
Marionette Client and Harness
Type:
defect

Tracking

(firefox-esr115 unaffected, firefox-esr128 unaffected, firefox131 unaffected, firefox132+ fixed, firefox133+ fixed)

Status:
RESOLVED FIXED
Milestone:
133 Branch
Tracking Flags:
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?

Flags: needinfo?(jmaher)
Regressed by: 1916456
No longer regressed by: 1920319

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.

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"]

Flags: needinfo?(jmaher)

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.

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?

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?

oh, good idea bug 1921411 could fix this and make more things balanced, I can give it a try.

The fix for bug 1921411 should be close for landing, so lets hope it fixes the perma failure for sure.

Depends on: 1921411

: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.

Flags: needinfo?(jmaher)

waiting on final review in bug 1921411

Severity: -- → S2
Flags: needinfo?(jmaher)
Priority: -- → P1

Fixed by bug 1921411.

Assignee: nobody → jmaher
Status: NEW → RESOLVED
Closed: 4 months ago
status-firefox132: affected → fixed
status-firefox133: affected → fixed
Resolution: --- → FIXED
Target Milestone: --- → 133 Branch
You need to log in before you can comment on or make changes to this bug.