Open
Bug 1948649
Opened 27 days ago
Updated 21 days ago
Intermittent [tier 2] toolkit/modules/tests/marionette/test_first_startup.py | single tracking bug
Categories
(Toolkit :: General, defect, P5)
Toolkit
General
Tracking
()
NEW
People
(Reporter: intermittent-bug-filer, Unassigned)
Details
(Keywords: intermittent-failure, intermittent-testcase)
Filed by: amarc [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=495275221&repo=mozilla-central
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/RDNVhIayTcGZbkghoeZdtg/runs/0/artifacts/public/logs/live_backing.log
[task 2025-02-17T10:43:44.593Z] 10:43:44 INFO - TEST-START | toolkit/modules/tests/marionette/test_first_startup.py TestFirstStartup.test_existing_profile
[task 2025-02-17T10:43:44.593Z] 10:43:44 INFO - 1739789024589 Marionette DEBUG Closed connection 1
[task 2025-02-17T10:43:44.594Z] 10:43:44 INFO - 1739789024594 Marionette DEBUG Accepted connection 2 from 127.0.0.1:44056
[task 2025-02-17T10:43:44.597Z] 10:43:44 INFO - 1739789024597 Marionette DEBUG 2 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
[task 2025-02-17T10:43:44.599Z] 10:43:44 INFO - 1739789024599 Marionette DEBUG Waiting for initial application window
[task 2025-02-17T10:43:44.602Z] 10:43:44 INFO - 1739789024602 RemoteAgent TRACE [9] ProgressListener Start: expectNavigation=false resolveWhenStarted=false unloadTimeout=80000 waitForExplicitStart=false
[task 2025-02-17T10:43:44.603Z] 10:43:44 INFO - 1739789024602 RemoteAgent TRACE [9] ProgressListener Setting unload timer (80000ms)
[task 2025-02-17T10:43:44.603Z] 10:43:44 INFO - 1739789024603 RemoteAgent TRACE [9] Wait for initial navigation: isInitial=false, isLoadingDocument=false
[task 2025-02-17T10:43:44.604Z] 10:43:44 INFO - 1739789024604 RemoteAgent TRACE [9] Document already finished loading: about:blank
[task 2025-02-17T10:43:44.604Z] 10:43:44 INFO - 1739789024604 RemoteAgent TRACE [9] ProgressListener Stop: has error=false url=about:blank
[task 2025-02-17T10:43:44.608Z] 10:43:44 INFO - 1739789024607 Marionette DEBUG 2 <- [1,1,null,{"sessionId":"f2ca23b3-b18a-40ac-a9f7-0b1527c58cfb","capabilities":{"acceptInsecureCerts":false,"browserName":"firefox","browserVersion":"137.0a1","platformName":"linux","unhandledPromptBehavior":"dismiss and notify","userAgent":"Mozilla/5.0 (X11; Linux x86_64; rv:137.0) Gecko/20100101 Firefox/137.0","moz:buildID":"20250217092040","moz:headless":false,"moz:platformVersion":"4.4.0-1014-aws","moz:processID":4484,"moz:profile":"/tmp/tmpa361qqdh.mozrunner","moz:shutdownTimeout":180000,"pageLoadStrategy":"normal","timeouts":{"implicit":0,"pageLoad":300000,"script":30000},"setWindowRect":true,"strictFileInteractability":true,"moz:accessibilityChecks":false,"moz:webdriverClick":true,"moz:windowless":false,"proxy":{}}}]
[task 2025-02-17T10:43:44.610Z] 10:43:44 INFO - 1739789024609 Marionette DEBUG 2 -> [0,2,"WebDriver:SetTimeouts",{"script":30000}]
[task 2025-02-17T10:43:44.611Z] 10:43:44 INFO - 1739789024611 Marionette DEBUG 2 <- [1,2,null,{"value":null}]
[task 2025-02-17T10:43:44.613Z] 10:43:44 INFO - 1739789024613 Marionette DEBUG 2 -> [0,3,"WebDriver:SetTimeouts",{"pageLoad":300000}]
[task 2025-02-17T10:43:44.615Z] 10:43:44 INFO - 1739789024615 Marionette DEBUG 2 <- [1,3,null,{"value":null}]
[task 2025-02-17T10:43:44.616Z] 10:43:44 INFO - 1739789024616 Marionette DEBUG 2 -> [0,4,"WebDriver:SetTimeouts",{"implicit":0}]
[task 2025-02-17T10:43:44.618Z] 10:43:44 INFO - 1739789024617 Marionette DEBUG 2 <- [1,4,null,{"value":null}]
[task 2025-02-17T10:43:44.619Z] 10:43:44 INFO - 1739789024619 Marionette DEBUG 2 -> [0,5,"Marionette:AcceptConnections",{"value":false}]
[task 2025-02-17T10:43:44.621Z] 10:43:44 INFO - 1739789024620 Marionette INFO Stopped listening on port 2828
[task 2025-02-17T10:43:44.622Z] 10:43:44 INFO - 1739789024622 Marionette DEBUG 2 <- [1,5,null,{"value":null}]
[task 2025-02-17T10:43:44.624Z] 10:43:44 INFO - 1739789024624 Marionette DEBUG 2 -> [0,6,"Marionette:Quit",{}]
[task 2025-02-17T10:43:45.194Z] 10:43:45 INFO - [CodeCoverage] Setting handlers for process 4668.
[task 2025-02-17T10:43:45.387Z] 10:43:45 INFO - [CodeCoverage] Setting handlers for process 4671.
[task 2025-02-17T10:43:45.421Z] 10:43:45 INFO - [CodeCoverage] Setting handlers for process 4672.
[task 2025-02-17T10:43:45.568Z] 10:43:45 INFO - 1739789025567 Marionette TRACE Received observer notification quit-application
[task 2025-02-17T10:43:45.578Z] 10:43:45 INFO - 1739789025577 Marionette TRACE Received observer notification quit-application
[task 2025-02-17T10:43:45.583Z] 10:43:45 INFO - 1739789025583 Marionette DEBUG Marionette stopped listening
[task 2025-02-17T10:43:45.584Z] 10:43:45 INFO - 1739789025584 Marionette DEBUG 2 <- [1,6,null,{"cause":"shutdown","forced":false,"in_app":true}]
[task 2025-02-17T10:43:45.592Z] 10:43:45 INFO - 1739789025591 Marionette DEBUG Closed connection 2
[task 2025-02-17T10:43:47.114Z] 10:43:47 INFO - [Parent 4484, IPC I/O Parent] WARNING: Process 4665 may be hanging at shutdown; will wait for up to 80000ms: file /builds/worker/checkouts/gecko/ipc/chromium/src/chrome/common/process_watcher_posix_sigchld.cc:203
[task 2025-02-17T10:43:47.710Z] 10:43:47 INFO - Application command: /builds/worker/workspace/build/application/firefox/firefox -marionette -first-startup -profile /tmp/tmpa361qqdh.mozrunner
[task 2025-02-17T10:43:47.764Z] 10:43:47 INFO - [CodeCoverage] Setting handlers for process 4767.
[task 2025-02-17T10:43:47.901Z] 10:43:47 INFO - ATTENTION: default value of option mesa_glthread overridden by environment.
[task 2025-02-17T10:43:47.930Z] 10:43:47 INFO - ATTENTION: default value of option mesa_glthread overridden by environment.
[task 2025-02-17T10:43:48.187Z] 10:43:48 INFO - 1739789028186 Marionette INFO Marionette enabled
[task 2025-02-17T10:43:48.187Z] 10:43:48 INFO - 1739789028187 Marionette TRACE Received observer notification final-ui-startup
[task 2025-02-17T10:43:48.224Z] 10:43:48 INFO - 1739789028223 Marionette INFO Listening on port 2828
[task 2025-02-17T10:43:48.224Z] 10:43:48 INFO - 1739789028224 Marionette DEBUG Marionette is listening
[task 2025-02-17T10:43:48.288Z] 10:43:48 INFO - 1739789028287 Marionette DEBUG Accepted connection 0 from 127.0.0.1:44068
[task 2025-02-17T10:43:48.326Z] 10:43:48 INFO - 1739789028325 Marionette DEBUG Closed connection 0
[task 2025-02-17T10:43:48.326Z] 10:43:48 INFO - 1739789028326 Marionette DEBUG Accepted connection 1 from 127.0.0.1:44070
[task 2025-02-17T10:43:48.446Z] 10:43:48 INFO - 1739789028446 Marionette DEBUG 1 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
[task 2025-02-17T10:43:48.449Z] 10:43:48 INFO - 1739789028448 Marionette DEBUG Waiting for initial application window
[task 2025-02-17T10:43:49.030Z] 10:43:49 INFO - [CodeCoverage] Setting handlers for process 4866.
[task 2025-02-17T10:43:50.029Z] 10:43:50 INFO - console.error: ({})
[task 2025-02-17T10:43:50.728Z] 10:43:50 INFO - 1739789030727 Marionette TRACE Received observer notification browser-idle-startup-tasks-finished
[task 2025-02-17T10:43:50.733Z] 10:43:50 INFO - 1739789030733 RemoteAgent TRACE [3] ProgressListener Start: expectNavigation=false resolveWhenStarted=false unloadTimeout=80000 waitForExplicitStart=false
[task 2025-02-17T10:43:50.734Z] 10:43:50 INFO - 1739789030733 RemoteAgent TRACE [3] ProgressListener Document already loading about:blank
[task 2025-02-17T10:43:50.734Z] 10:43:50 INFO - 1739789030733 RemoteAgent TRACE [3] ProgressListener Loading state: isStart=true isStop=false status=0x0, loadType=0x1
[task 2025-02-17T10:43:50.734Z] 10:43:50 INFO - 1739789030734 RemoteAgent TRACE [3] ProgressListener Started loading about:blank
[task 2025-02-17T10:43:50.735Z] 10:43:50 INFO - 1739789030734 RemoteAgent TRACE [3] Wait for initial navigation: isInitial=true, isLoadingDocument=true
[task 2025-02-17T10:49:48.338Z] 10:49:48 INFO - 1739789388337 Marionette DEBUG Failed to remove observer "browser-delayed-startup-finished"
[task 2025-02-17T10:49:48.342Z] 10:49:48 INFO - 1739789388342 Marionette DEBUG Closed connection 1
[task 2025-02-17T10:52:58.380Z] 10:52:58 INFO - TEST-UNEXPECTED-ERROR | toolkit/modules/tests/marionette/test_first_startup.py TestFirstStartup.test_existing_profile | OSError: Process has been unexpectedly closed (Exit code: -15) (Reason: Process killed because the connection to Marionette server is lost. Check gecko.log for errors (Reason: Connection timed out after 360.0s))
[task 2025-02-17T10:52:58.380Z] 10:52:58 INFO - Traceback (most recent call last):
[task 2025-02-17T10:52:58.380Z] 10:52:58 INFO - File "/builds/worker/workspace/build/venv/lib/python3.8/site-packages/marionette_harness/marionette_test/testcases.py", line 198, in run
[task 2025-02-17T10:52:58.380Z] 10:52:58 INFO - testMethod()
[task 2025-02-17T10:52:58.380Z] 10:52:58 INFO - File "/builds/worker/workspace/build/tests/marionette/tests/toolkit/modules/tests/marionette/test_first_startup.py", line 45, in test_existing_profile
[task 2025-02-17T10:52:58.380Z] 10:52:58 INFO - self.marionette.start_session()
[task 2025-02-17T10:52:58.380Z] 10:52:58 INFO - File "/builds/worker/workspace/build/venv/lib/python3.8/site-packages/marionette_driver/decorators.py", line 34, in _
[task 2025-02-17T10:52:58.380Z] 10:52:58 INFO - m._handle_socket_failure()
[task 2025-02-17T10:52:58.381Z] 10:52:58 INFO - File "/builds/worker/workspace/build/venv/lib/python3.8/site-packages/marionette_driver/marionette.py", line 853, in _handle_socket_failure
[task 2025-02-17T10:52:58.381Z] 10:52:58 INFO - reraise(
[task 2025-02-17T10:52:58.381Z] 10:52:58 INFO - File "/builds/worker/workspace/build/venv/lib/python3.8/site-packages/six.py", line 718, in reraise
[task 2025-02-17T10:52:58.381Z] 10:52:58 INFO - raise value.with_traceback(tb)
[task 2025-02-17T10:52:58.381Z] 10:52:58 INFO - File "/builds/worker/workspace/build/venv/lib/python3.8/site-packages/marionette_driver/decorators.py", line 24, in _
[task 2025-02-17T10:52:58.381Z] 10:52:58 INFO - return func(*args, **kwargs)
[task 2025-02-17T10:52:58.381Z] 10:52:58 INFO - File "/builds/worker/workspace/build/venv/lib/python3.8/site-packages/marionette_driver/marionette.py", line 1374, in start_session
[task 2025-02-17T10:52:58.381Z] 10:52:58 INFO - resp = self._send_message("WebDriver:NewSession", capabilities)
[task 2025-02-17T10:52:58.381Z] 10:52:58 INFO - File "/builds/worker/workspace/build/venv/lib/python3.8/site-packages/marionette_driver/decorators.py", line 34, in _
[task 2025-02-17T10:52:58.381Z] 10:52:58 INFO - m._handle_socket_failure()
[task 2025-02-17T10:52:58.381Z] 10:52:58 INFO - File "/builds/worker/workspace/build/venv/lib/python3.8/site-packages/marionette_driver/marionette.py", line 853, in _handle_socket_failure
[task 2025-02-17T10:52:58.381Z] 10:52:58 INFO - reraise(
[task 2025-02-17T10:52:58.381Z] 10:52:58 INFO - File "/builds/worker/workspace/build/venv/lib/python3.8/site-packages/six.py", line 718, in reraise
[task 2025-02-17T10:52:58.381Z] 10:52:58 INFO - raise value.with_traceback(tb)
[task 2025-02-17T10:52:58.381Z] 10:52:58 INFO - File "/builds/worker/workspace/build/venv/lib/python3.8/site-packages/marionette_driver/decorators.py", line 24, in _
[task 2025-02-17T10:52:58.381Z] 10:52:58 INFO - return func(*args, **kwargs)
[task 2025-02-17T10:52:58.382Z] 10:52:58 INFO - File "/builds/worker/workspace/build/venv/lib/python3.8/site-packages/marionette_driver/marionette.py", line 769, in _send_message
[task 2025-02-17T10:52:58.382Z] 10:52:58 INFO - msg = self.client.request(name, params)
[task 2025-02-17T10:52:58.382Z] 10:52:58 INFO - File "/builds/worker/workspace/build/venv/lib/python3.8/site-packages/marionette_driver/transport.py", line 382, in request
[task 2025-02-17T10:52:58.382Z] 10:52:58 INFO - return self.receive()
[task 2025-02-17T10:52:58.382Z] 10:52:58 INFO - File "/builds/worker/workspace/build/venv/lib/python3.8/site-packages/marionette_driver/transport.py", line 218, in receive
[task 2025-02-17T10:52:58.382Z] 10:52:58 INFO - raise socket.timeout(
[task 2025-02-17T10:52:58.382Z] 10:52:58 INFO - TEST-INFO took 553786ms
[task 2025-02-17T10:52:58.382Z] 10:52:58 INFO - Application command: /builds/worker/workspace/build/application/firefox/firefox -marionette -first-startup -profile /tmp/tmpoc_v7c_g.mozrunner
[task 2025-02-17T10:52:58.433Z] 10:52:58 INFO - [CodeCoverage] Setting handlers for process 4948.
[task 2025-02-17T10:52:59.080Z] 10:52:59 INFO - ATTENTION: default value of option mesa_glthread overridden by environment.
[task 2025-02-17T10:52:59.123Z] 10:52:59 INFO - 1739789579122 Marionette INFO Marionette enabled
[task 2025-02-17T10:52:59.125Z] 10:52:59 INFO - 1739789579125 Marionette TRACE Received observer notification final-ui-startup
[task 2025-02-17T10:52:59.213Z] 10:52:59 INFO - 1739789579212 Marionette INFO Listening on port 2828
[task 2025-02-17T10:52:59.216Z] 10:52:59 INFO - 1739789579215 Marionette DEBUG Marionette is listening
[task 2025-02-17T10:52:59.251Z] 10:52:59 INFO - 1739789579251 Marionette DEBUG Accepted connection 0 from 127.0.0.1:44140
[task 2025-02-17T10:52:59.276Z] 10:52:59 INFO - 1739789579276 Marionette DEBUG Closed connection 0
[task 2025-02-17T10:52:59.277Z] 10:52:59 INFO - 1739789579276 Marionette DEBUG Accepted connection 1 from 127.0.0.1:44142
[task 2025-02-17T10:52:59.432Z] 10:52:59 INFO - 1739789579431 Marionette DEBUG 1 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
[task 2025-02-17T10:52:59.438Z] 10:52:59 INFO - 1739789579437 Marionette DEBUG Waiting for initial application window
[task 2025-02-17T10:52:59.757Z] 10:52:59 INFO - ATTENTION: default value of option mesa_glthread overridden by environment.
[task 2025-02-17T10:53:00.142Z] 10:53:00 INFO - [CodeCoverage] Setting handlers for process 5027.
[task 2025-02-17T10:53:00.778Z] 10:53:00 INFO - [CodeCoverage] Setting handlers for process 5071.
[task 2025-02-17T10:53:02.336Z] 10:53:02 INFO - console.error: ({})
[task 2025-02-17T10:53:04.069Z] 10:53:04 INFO - 1739789584069 Marionette TRACE Received observer notification browser-idle-startup-tasks-finished
[task 2025-02-17T10:53:04.086Z] 10:53:04 INFO - 1739789584085 RemoteAgent TRACE [9] ProgressListener Start: expectNavigation=false resolveWhenStarted=false unloadTimeout=80000 waitForExplicitStart=false
[task 2025-02-17T10:53:04.089Z] 10:53:04 INFO - 1739789584086 RemoteAgent TRACE [9] ProgressListener Setting unload timer (80000ms)
[task 2025-02-17T10:53:04.093Z] 10:53:04 INFO - 1739789584087 RemoteAgent TRACE [9] Wait for initial navigation: isInitial=false, isLoadingDocument=false
[task 2025-02-17T10:53:04.096Z] 10:53:04 INFO - 1739789584087 RemoteAgent TRACE [9] Document already finished loading: about:blank
[task 2025-02-17T10:53:04.098Z] 10:53:04 INFO - 1739789584087 RemoteAgent TRACE [9] ProgressListener Stop: has error=false url=about:blank
[task 2025-02-17T10:53:04.116Z] 10:53:04 INFO - 1739789584115 Marionette DEBUG 1 <- [1,1,null,{"sessionId":"021c8e4e-cb80-4ca9-b19b-aaf60daa947a","capabilities":{"acceptInsecureCerts":false,"browserName":"firefox","browserVersion":"137.0a1","platformName":"linux","unhandledPromptBehavior":"dismiss and notify","userAgent":"Mozilla/5.0 (X11; Linux x86_64; rv:137.0) Gecko/20100101 Firefox/137.0","moz:buildID":"20250217092040","moz:headless":false,"moz:platformVersion":"4.4.0-1014-aws","moz:processID":4948,"moz:profile":"/tmp/tmpoc_v7c_g.mozrunner","moz:shutdownTimeout":180000,"pageLoadStrategy":"normal","timeouts":{"implicit":0,"pageLoad":300000,"script":30000},"setWindowRect":true,"strictFileInteractability":true,"moz:accessibilityChecks":false,"moz:webdriverClick":true,"moz:windowless":false,"proxy":{}}}]
[task 2025-02-17T10:53:04.137Z] 10:53:04 INFO - 1739789584137 Marionette DEBUG 1 -> [0,2,"WebDriver:DeleteSession",{}]
[task 2025-02-17T10:53:04.140Z] 10:53:04 INFO - 1739789584140 Marionette DEBUG 1 <- [1,2,null,{"value":null}]
[task 2025-02-17T10:53:04.143Z] 10:53:04 INFO - TEST-START | toolkit/modules/tests/marionette/test_first_startup.py TestFirstStartup.test_new_profile
| Comment hidden (Intermittent Failures Robot) |
You need to log in
before you can comment on or make changes to this bug.
Description
•