Closed
Bug 1814653
Opened 2 years ago
Closed 1 year ago
Intermittent toolkit/xre/test/marionette/test_win32k_enrollment.py TestWin32kAutostart.test_6 | OSError: Process killed because the connection to Marionette server is lost. Check gecko.log for errors (Reason: Timed out waiting for connection on
Categories
(Toolkit :: Startup and Profile System, defect, P5)
Toolkit
Startup and Profile System
Tracking
()
RESOLVED
INCOMPLETE
People
(Reporter: intermittent-bug-filer, Unassigned)
Details
(Keywords: intermittent-failure)
Filed by: ctuns [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=404346171&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/bBv76gvYRwiygmlhkDz7vQ/runs/0/artifacts/public/logs/live_backing.log
[task 2023-02-02T14:35:42.207Z] 14:35:42 INFO - TEST-START | toolkit/xre/test/marionette/test_win32k_enrollment.py TestWin32kAutostart.test_6
[task 2023-02-02T14:35:42.208Z] 14:35:42 INFO - 1675348542208 Marionette DEBUG Accepted connection 3 from 127.0.0.1:53057
[task 2023-02-02T14:35:42.209Z] 14:35:42 INFO - 1675348542209 Marionette DEBUG 3 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
[task 2023-02-02T14:35:42.210Z] 14:35:42 INFO - 1675348542210 Marionette DEBUG Waiting for initial application window
[task 2023-02-02T14:35:42.210Z] 14:35:42 INFO - 1675348542210 RemoteAgent TRACE [9] ProgressListener Start: expectNavigation=false resolveWhenStarted=false unloadTimeout=200 waitForExplicitStart=false
[task 2023-02-02T14:35:42.211Z] 14:35:42 INFO - 1675348542210 RemoteAgent TRACE [9] ProgressListener Setting unload timer (200ms)
[task 2023-02-02T14:35:42.211Z] 14:35:42 INFO - 1675348542211 RemoteAgent TRACE [9] Document already finished loading: about:blank
[task 2023-02-02T14:35:42.212Z] 14:35:42 INFO - 1675348542211 RemoteAgent TRACE [9] ProgressListener Stop: has error=false
[task 2023-02-02T14:35:42.214Z] 14:35:42 INFO - 1675348542213 Marionette DEBUG 3 <- [1,1,null,{"sessionId":"49dd2893-df8f-4919-afbb-ac409a7791a9","capabilities":{"browserName":"firefox","browserVersion":"111.0a1","platformName":"windows","acceptInsecureCerts":false,"pageLoadStrategy":"normal","setWindowRect":true,"timeouts":{"implicit":0,"pageLoad":300000,"script":30000},"strictFileInteractability":true,"unhandledPromptBehavior":"dismiss and notify","moz:accessibilityChecks":false,"moz:buildID":"20230202134829","moz:headless":false,"moz:platformVersion":"10.0","moz:processID":6636,"moz:profile":"C:\\Users\\task_167534446186185\\AppData\\Local\\Temp\\tmpyos8of9k.mozrunner","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true,"moz:windowless":false,"proxy":{}}}]
[task 2023-02-02T14:35:42.214Z] 14:35:42 INFO - 1675348542214 Marionette DEBUG 3 -> [0,2,"WebDriver:SetTimeouts",{"script":30000}]
[task 2023-02-02T14:35:42.214Z] 14:35:42 INFO - 1675348542214 Marionette DEBUG 3 <- [1,2,null,{"value":null}]
[task 2023-02-02T14:35:42.215Z] 14:35:42 INFO - 1675348542215 Marionette DEBUG 3 -> [0,3,"WebDriver:SetTimeouts",{"pageLoad":300000}]
[task 2023-02-02T14:35:42.215Z] 14:35:42 INFO - 1675348542215 Marionette DEBUG 3 <- [1,3,null,{"value":null}]
[task 2023-02-02T14:35:42.216Z] 14:35:42 INFO - 1675348542216 Marionette DEBUG 3 -> [0,4,"WebDriver:SetTimeouts",{"implicit":0}]
[task 2023-02-02T14:35:42.216Z] 14:35:42 INFO - 1675348542216 Marionette DEBUG 3 <- [1,4,null,{"value":null}]
[task 2023-02-02T14:35:42.217Z] 14:35:42 INFO - 1675348542217 Marionette DEBUG 3 -> [0,5,"Marionette:SetContext",{"value":"chrome"}]
[task 2023-02-02T14:35:42.217Z] 14:35:42 INFO - 1675348542217 Marionette DEBUG 3 <- [1,5,null,{"value":null}]
[task 2023-02-02T14:35:42.218Z] 14:35:42 INFO - 1675348542218 Marionette DEBUG 3 -> [0,6,"Marionette:GetContext",{}]
[task 2023-02-02T14:35:42.218Z] 14:35:42 INFO - 1675348542218 Marionette DEBUG 3 <- [1,6,null,{"value":"chrome"}]
[task 2023-02-02T14:35:42.219Z] 14:35:42 INFO - 1675348542219 Marionette DEBUG 3 -> [0,7,"Marionette:SetContext",{"value":"chrome"}]
[task 2023-02-02T14:35:42.219Z] 14:35:42 INFO - 1675348542219 Marionette DEBUG 3 <- [1,7,null,{"value":null}]
[task 2023-02-02T14:35:42.221Z] 14:35:42 INFO - 1675348542220 Marionette DEBUG 3 -> [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":"Z:\\task_167534446186185\\build\\tests\\marionette\\tests\\toolkit\\xre\\test\\marionette\\test_win32k_enrollment.py"}]
[task 2023-02-02T14:35:42.223Z] 14:35:42 INFO - 1675348542223 RemoteAgent TRACE WebDriverProcessData actor created for PID 6636
[task 2023-02-02T14:35:42.225Z] 14:35:42 INFO - 1675348542225 Marionette TRACE [1] MarionetteCommands actor created for window id 2
[task 2023-02-02T14:35:42.226Z] 14:35:42 INFO - 1675348542227 Marionette DEBUG 3 <- [1,8,null,{"value":null}]
[task 2023-02-02T14:35:42.228Z] 14:35:42 INFO - 1675348542228 Marionette DEBUG 3 -> [0,9,"Marionette:SetContext",{"value":"chrome"}]
[task 2023-02-02T14:35:42.228Z] 14:35:42 INFO - 1675348542228 Marionette DEBUG 3 <- [1,9,null,{"value":null}]
[task 2023-02-02T14:35:42.229Z] 14:35:42 INFO - 1675348542229 Marionette DEBUG 3 -> [0,10,"Marionette:GetContext",{}]
[task 2023-02-02T14:35:42.229Z] 14:35:42 INFO - 1675348542229 Marionette DEBUG 3 <- [1,10,null,{"value":"chrome"}]
[task 2023-02-02T14:35:42.230Z] 14:35:42 INFO - 1675348542229 Marionette DEBUG 3 -> [0,11,"Marionette:SetContext",{"value":"chrome"}]
[task 2023-02-02T14:35:42.230Z] 14:35:42 INFO - 1675348542230 Marionette DEBUG 3 <- [1,11,null,{"value":null}]
[task 2023-02-02T14:35:42.231Z] 14:35:42 INFO - 1675348542231 Marionette DEBUG 3 -> [0,12,"WebDriver:ExecuteScript",{"script":"return Services.prefs.getBoolPref(\"security.sandbox.content.win32k-disable\");","args":[],"newSandbox":false,"sandbox":"win32k-autostart","line":49,"filename":"Z:\\task_167534446186185\\build\\tests\\marionette\\tests\\toolkit\\xre\\test\\marionette\\test_win32k_enrollment.py"}]
[task 2023-02-02T14:35:42.232Z] 14:35:42 INFO - 1675348542232 Marionette DEBUG 3 <- [1,12,null,{"value":true}]
[task 2023-02-02T14:35:42.233Z] 14:35:42 INFO - 1675348542233 Marionette DEBUG 3 -> [0,13,"Marionette:SetContext",{"value":"chrome"}]
[task 2023-02-02T14:35:42.233Z] 14:35:42 INFO - 1675348542233 Marionette DEBUG 3 <- [1,13,null,{"value":null}]
[task 2023-02-02T14:35:42.233Z] 14:35:42 INFO - 1675348542234 Marionette DEBUG 3 -> [0,14,"Marionette:GetContext",{}]
[task 2023-02-02T14:35:42.234Z] 14:35:42 INFO - 1675348542234 Marionette DEBUG 3 <- [1,14,null,{"value":"chrome"}]
[task 2023-02-02T14:35:42.235Z] 14:35:42 INFO - 1675348542235 Marionette DEBUG 3 -> [0,15,"Marionette:SetContext",{"value":"chrome"}]
[task 2023-02-02T14:35:42.235Z] 14:35:42 INFO - 1675348542235 Marionette DEBUG 3 <- [1,15,null,{"value":null}]
[task 2023-02-02T14:35:42.236Z] 14:35:42 INFO - 1675348542236 Marionette DEBUG 3 -> [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":"Z:\\task_167534446186185\\build\\tests\\marionette\\tests\\toolkit\\xre\\test\\marionette\\test_win32k_enrollment.py"}]
[task 2023-02-02T14:35:42.237Z] 14:35:42 INFO - 1675348542237 Marionette DEBUG 3 <- [1,16,null,{"value":{"win32kSessionStatus":15,"win32kStatus":15,"win32kExperimentStatus":0,"win32kPref":true,"win32kStartupEnrollmentStatusPref":0}}]
[task 2023-02-02T14:35:42.238Z] 14:35:42 INFO - 1675348542238 Marionette DEBUG 3 -> [0,17,"Marionette:SetContext",{"value":"chrome"}]
[task 2023-02-02T14:35:42.238Z] 14:35:42 INFO - 1675348542238 Marionette DEBUG 3 <- [1,17,null,{"value":null}]
[task 2023-02-02T14:35:42.239Z] 14:35:42 INFO - 1675348542239 Marionette DEBUG 3 -> [0,18,"Marionette:GetContext",{}]
[task 2023-02-02T14:35:42.239Z] 14:35:42 INFO - 1675348542239 Marionette DEBUG 3 <- [1,18,null,{"value":"chrome"}]
[task 2023-02-02T14:35:42.239Z] 14:35:42 INFO - 1675348542239 Marionette DEBUG 3 -> [0,19,"WebDriver:DeleteSession",{}]
[task 2023-02-02T14:35:42.240Z] 14:35:42 INFO - 1675348542240 Marionette TRACE [1] MarionetteCommands actor destroyed for window id 2
[task 2023-02-02T14:35:42.241Z] 14:35:42 INFO - 1675348542241 Marionette DEBUG 3 <- [1,19,null,{"value":null}]
[task 2023-02-02T14:35:42.242Z] 14:35:42 INFO - 1675348542242 Marionette DEBUG Closed connection 3
[task 2023-02-02T14:35:42.303Z] 14:35:42 INFO - Application command: Z:\task_167534446186185\build\application\firefox\firefox.exe -no-remote -marionette --wait-for-browser -profile C:\Users\task_167534446186185\AppData\Local\Temp\tmpui_sewqu.mozrunner
[task 2023-02-02T14:35:42.482Z] 14:35:42 INFO - DEBUG: Adding blocker AddonManager: shutting down. for phase profile-before-change
[task 2023-02-02T14:35:42.497Z] 14:35:42 INFO - DEBUG: Adding blocker IOUtils Blocker (profile-before-change) for phase profile-before-change
[task 2023-02-02T14:35:42.502Z] 14:35:42 INFO - DEBUG: Adding blocker IOUtils Blocker (profile-before-change-telemetry) for phase profile-before-change-telemetry
[task 2023-02-02T14:35:42.503Z] 14:35:42 INFO - DEBUG: Adding blocker IOUtils Blocker (profile-before-change) for phase IOUtils: waiting for sendTelemetry IO to complete
[task 2023-02-02T14:35:42.503Z] 14:35:42 INFO - DEBUG: Adding blocker IOUtils Blocker (xpcom-will-shutdown) for phase xpcom-will-shutdown
[task 2023-02-02T14:35:42.503Z] 14:35:42 INFO - DEBUG: Adding blocker IOUtils Blocker (profile-before-change-telemetry) for phase IOUtils: waiting for xpcomWillShutdown IO to complete
[task 2023-02-02T14:35:42.531Z] 14:35:42 INFO - DEBUG: Adding blocker Flush WebExtension StartupCache for phase IOUtils: waiting for profileBeforeChange IO to complete
[task 2023-02-02T14:35:42.628Z] 14:35:42 INFO - DEBUG: Adding blocker JSON store: writing data for 'addonStartup' for phase AddonManager: Waiting for providers to shut down.
[task 2023-02-02T14:35:42.636Z] 14:35:42 INFO - DEBUG: Adding blocker Update add-on blocklist state into add-on DB for phase AddonManager: Waiting to start provider shutdown.
[task 2023-02-02T14:35:42.639Z] 14:35:42 INFO - DEBUG: Adding blocker XPIProvider shutdown for phase quit-application-granted
[task 2023-02-02T14:35:42.640Z] 14:35:42 INFO - DEBUG: Adding blocker XPIProvider for phase AddonManager: Waiting for providers to shut down.
[task 2023-02-02T14:35:42.641Z] 14:35:42 INFO - DEBUG: Adding blocker ServiceWorkerRegistrar: Flushing data for phase profile-before-change
[task 2023-02-02T14:35:42.643Z] 14:35:42 INFO - DEBUG: Adding blocker CrashMonitor: Writing notifications to file after receiving profile-before-change and awaiting all checkpoints written for phase IOUtils: waiting for profileBeforeChange IO to complete
[task 2023-02-02T14:35:42.654Z] 14:35:42 INFO - DEBUG: Adding blocker TelemetryController: shutting down for phase profile-before-change-telemetry
[task 2023-02-02T14:35:42.691Z] 14:35:42 INFO - DEBUG: Adding blocker EnvironmentAddonBuilder for phase AddonManager: Waiting to start provider shutdown.
[task 2023-02-02T14:35:42.701Z] 14:35:42 INFO - DEBUG: Adding blocker RemoteSettingsClient - finish IDB access. for phase profile-before-change
[task 2023-02-02T14:35:42.703Z] 14:35:42 INFO - DEBUG: Adding blocker TerminatoryTelemetry: Waiting to submit telemetry for phase IOUtils: waiting for sendTelemetry IO to complete
[task 2023-02-02T14:35:42.706Z] 14:35:42 INFO - 1675348542705 Marionette INFO Marionette enabled
[task 2023-02-02T14:35:42.707Z] 14:35:42 INFO - 1675348542707 Marionette TRACE Received observer notification final-ui-startup
[task 2023-02-02T14:35:42.709Z] 14:35:42 INFO - 1675348542709 Marionette INFO Listening on port 2828
[task 2023-02-02T14:35:42.709Z] 14:35:42 INFO - 1675348542709 Marionette DEBUG Marionette is listening
[task 2023-02-02T14:38:54.424Z] 14:38:54 ERROR - TEST-UNEXPECTED-ERROR | toolkit/xre/test/marionette/test_win32k_enrollment.py TestWin32kAutostart.test_6 | OSError: Process killed because the connection to Marionette server is lost. Check gecko.log for errors (Reason: Timed out waiting for connection on 127.0.0.1:2828!)
[task 2023-02-02T14:38:54.431Z] 14:38:54 INFO - Traceback (most recent call last):
[task 2023-02-02T14:38:54.431Z] 14:38:54 INFO - File "Z:\task_167534446186185\build\venv\lib\site-packages\marionette_harness\marionette_test\testcases.py", line 231, in run
[task 2023-02-02T14:38:54.431Z] 14:38:54 INFO - self.tearDown()
[task 2023-02-02T14:38:54.432Z] 14:38:54 INFO - File "Z:\task_167534446186185\build\tests\marionette\tests\toolkit\xre\test\marionette\test_win32k_enrollment.py", line 202, in tearDown
[task 2023-02-02T14:38:54.432Z] 14:38:54 INFO - self.marionette.restart(in_app=False, clean=True)
[task 2023-02-02T14:38:54.432Z] 14:38:54 INFO - File "Z:\task_167534446186185\build\venv\lib\site-packages\marionette_driver\decorators.py", line 34, in _
[task 2023-02-02T14:38:54.432Z] 14:38:54 INFO - m._handle_socket_failure()
[task 2023-02-02T14:38:54.433Z] 14:38:54 INFO - File "Z:\task_167534446186185\build\venv\lib\site-packages\marionette_driver\marionette.py", line 740, in _handle_socket_failure
[task 2023-02-02T14:38:54.433Z] 14:38:54 INFO - reraise(
[task 2023-02-02T14:38:54.433Z] 14:38:54 INFO - File "Z:\task_167534446186185\build\venv\lib\site-packages\six.py", line 702, in reraise
[task 2023-02-02T14:38:54.433Z] 14:38:54 INFO - raise value.with_traceback(tb)
[task 2023-02-02T14:38:54.434Z] 14:38:54 INFO - File "Z:\task_167534446186185\build\venv\lib\site-packages\marionette_driver\decorators.py", line 24, in _
[task 2023-02-02T14:38:54.434Z] 14:38:54 INFO - return func(*args, **kwargs)
[task 2023-02-02T14:38:54.434Z] 14:38:54 INFO - File "Z:\task_167534446186185\build\venv\lib\site-packages\marionette_driver\marionette.py", line 1189, in restart
[task 2023-02-02T14:38:54.434Z] 14:38:54 INFO - self.raise_for_port(timeout=self.DEFAULT_STARTUP_TIMEOUT)
[task 2023-02-02T14:38:54.435Z] 14:38:54 INFO - File "Z:\task_167534446186185\build\venv\lib\site-packages\marionette_driver\marionette.py", line 631, in raise_for_port
[task 2023-02-02T14:38:54.435Z] 14:38:54 INFO - raise socket.timeout(
[task 2023-02-02T14:38:54.435Z] 14:38:54 INFO - TEST-INFO took 192201ms
[task 2023-02-02T14:38:54.435Z] 14:38:54 INFO - TEST-START | toolkit/xre/test/marionette/test_win32k_enrollment.py TestWin32kAutostart.test_7
| Comment hidden (Intermittent Failures Robot) |
|
||
Comment 2•1 year ago
|
||
https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit BugBot documentation.
Status: NEW → RESOLVED
Closed: 1 year ago
Resolution: --- → INCOMPLETE
You need to log in
before you can comment on or make changes to this bug.
Description
•