Closed
Bug 1881920
Opened 2 years ago
Closed 2 years ago
Intermittent testing/marionette/harness/marionette_harness/tests/unit/test_quit_restart.py TestQuitRestart.test_force_restart | single tracking bug
Categories
(Testing :: Marionette Client and Harness, defect, P5)
Testing
Marionette Client and Harness
Tracking
(Not tracked)
RESOLVED
INCOMPLETE
People
(Reporter: intermittent-bug-filer, Unassigned)
Details
(Keywords: intermittent-failure, intermittent-testcase)
Filed by: ctuns [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=448348437&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/UdP29zFNRV2HAgNB3em48A/runs/0/artifacts/public/logs/live_backing.log
[task 2024-02-24T19:02:03.220Z] 19:02:03 INFO - TEST-START | testing/marionette/harness/marionette_harness/tests/unit/test_quit_restart.py TestQuitRestart.test_force_restart
[task 2024-02-24T19:02:03.223Z] 19:02:03 INFO - 1708801323222 Marionette DEBUG Accepted connection 2 from 127.0.0.1:58448
[task 2024-02-24T19:02:03.224Z] 19:02:03 INFO - 1708801323223 Marionette DEBUG Closed connection 1
[task 2024-02-24T19:02:03.227Z] 19:02:03 INFO - 1708801323227 Marionette DEBUG 2 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
[task 2024-02-24T19:02:03.229Z] 19:02:03 INFO - 1708801323228 Marionette DEBUG Waiting for initial application window
[task 2024-02-24T19:02:03.230Z] 19:02:03 INFO - 1708801323230 RemoteAgent TRACE [3] ProgressListener Start: expectNavigation=false resolveWhenStarted=false unloadTimeout=5000 waitForExplicitStart=false
[task 2024-02-24T19:02:03.231Z] 19:02:03 INFO - 1708801323230 RemoteAgent TRACE [3] ProgressListener Setting unload timer (5000ms)
[task 2024-02-24T19:02:03.231Z] 19:02:03 INFO - 1708801323230 RemoteAgent TRACE [3] Document already finished loading: about:blank
[task 2024-02-24T19:02:03.231Z] 19:02:03 INFO - 1708801323230 RemoteAgent TRACE [3] ProgressListener Stop: has error=false
[task 2024-02-24T19:02:03.235Z] 19:02:03 INFO - 1708801323234 Marionette DEBUG 2 <- [1,1,null,{"sessionId":"bc248028-b555-401c-b15d-1cc7af307f2b","capabilities":{"browserName":"firefox","browserVersion":"125.0a1","platformName":"linux","acceptInsecureCerts":false,"pageLoadStrategy":"normal","setWindowRect":true,"timeouts":{"implicit":0,"pageLoad":300000,"script":30000},"strictFileInteractability":true,"unhandledPromptBehavior":"dismiss and notify","moz:accessibilityChecks":false,"moz:buildID":"20240224181508","moz:headless":false,"moz:platformVersion":"4.4.0-1014-aws","moz:processID":22931,"moz:profile":"/tmp/tmptybb_9wz.mozrunner","moz:shutdownTimeout":60000,"moz:webdriverClick":true,"moz:windowless":false,"proxy":{}}}]
[task 2024-02-24T19:02:03.238Z] 19:02:03 INFO - 1708801323237 Marionette DEBUG 2 -> [0,2,"WebDriver:SetTimeouts",{"script":30000}]
[task 2024-02-24T19:02:03.238Z] 19:02:03 INFO - 1708801323238 Marionette DEBUG 2 <- [1,2,null,{"value":null}]
[task 2024-02-24T19:02:03.243Z] 19:02:03 INFO - 1708801323242 Marionette DEBUG 2 -> [0,3,"WebDriver:SetTimeouts",{"pageLoad":300000}]
[task 2024-02-24T19:02:03.243Z] 19:02:03 INFO - 1708801323243 Marionette DEBUG 2 <- [1,3,null,{"value":null}]
[task 2024-02-24T19:02:03.247Z] 19:02:03 INFO - 1708801323246 Marionette DEBUG 2 -> [0,4,"WebDriver:SetTimeouts",{"implicit":0}]
[task 2024-02-24T19:02:03.248Z] 19:02:03 INFO - 1708801323247 Marionette DEBUG 2 <- [1,4,null,{"value":null}]
[task 2024-02-24T19:02:03.251Z] 19:02:03 INFO - 1708801323251 Marionette DEBUG 2 -> [0,5,"Marionette:GetContext",{}]
[task 2024-02-24T19:02:03.252Z] 19:02:03 INFO - 1708801323251 Marionette DEBUG 2 <- [1,5,null,{"value":"content"}]
[task 2024-02-24T19:02:03.255Z] 19:02:03 INFO - 1708801323255 Marionette DEBUG 2 -> [0,6,"Marionette:SetContext",{"value":"chrome"}]
[task 2024-02-24T19:02:03.256Z] 19:02:03 INFO - 1708801323255 Marionette DEBUG 2 <- [1,6,null,{"value":null}]
[task 2024-02-24T19:02:03.259Z] 19:02:03 INFO - 1708801323259 Marionette DEBUG 2 -> [0,7,"WebDriver:ExecuteScript",{"script":"const { Preferences } = ChromeUtils.importESModule(\n \"resource://gre/modules/Preferences.sys.mjs\"\n ... Preferences({defaultBranch: defaultBranch});\n return prefs.get(pref, null, Components.interfaces[valueType]);","args":["startup.homepage_welcome_url",false,"unspecified"],"newSandbox":true,"sandbox":"default","line":905,"filename":"../../venv/lib/python3.8/site-packages/marionette_driver/marionette.py"}]
[task 2024-02-24T19:02:03.261Z] 19:02:03 INFO - 1708801323260 RemoteAgent TRACE WebDriverProcessData actor created for PID 22931
[task 2024-02-24T19:02:03.261Z] 19:02:03 INFO - 1708801323260 Marionette TRACE [1] MarionetteCommands actor created for window id 2
[task 2024-02-24T19:02:03.265Z] 19:02:03 INFO - 1708801323265 Marionette DEBUG 2 <- [1,7,null,{"value":"https://www.mozilla.org/projects/firefox/%VERSION%/firstrun/"}]
[task 2024-02-24T19:02:03.271Z] 19:02:03 INFO - 1708801323270 Marionette DEBUG 2 -> [0,8,"Marionette:SetContext",{"value":"content"}]
[task 2024-02-24T19:02:03.272Z] 19:02:03 INFO - 1708801323271 Marionette DEBUG 2 <- [1,8,null,{"value":null}]
[task 2024-02-24T19:02:03.273Z] 19:02:03 INFO - 1708801323272 Marionette DEBUG 2 -> [0,9,"Marionette:GetContext",{}]
[task 2024-02-24T19:02:03.273Z] 19:02:03 INFO - 1708801323272 Marionette DEBUG 2 <- [1,9,null,{"value":"content"}]
[task 2024-02-24T19:02:03.275Z] 19:02:03 INFO - 1708801323275 Marionette DEBUG 2 -> [0,10,"Marionette:SetContext",{"value":"chrome"}]
[task 2024-02-24T19:02:03.275Z] 19:02:03 INFO - 1708801323275 Marionette DEBUG 2 <- [1,10,null,{"value":null}]
[task 2024-02-24T19:02:03.278Z] 19:02:03 INFO - 1708801323278 Marionette DEBUG 2 -> [0,11,"WebDriver:ExecuteScript",{"script":"const { Preferences } = ChromeUtils.importESModule(\n \"resource://gre/modules/Preferences.sys.mjs\"\n ... guments[2];\n\n prefs = new Preferences({defaultBranch: defaultBranch});\n prefs.set(pref, value);","args":["startup.homepage_welcome_url","about:about",false],"newSandbox":true,"sandbox":"default","line":944,"filename":"../../venv/lib/python3.8/site-packages/marionette_driver/marionette.py"}]
[task 2024-02-24T19:02:03.284Z] 19:02:03 INFO - 1708801323284 Marionette DEBUG 2 <- [1,11,null,{"value":null}]
[task 2024-02-24T19:02:03.286Z] 19:02:03 INFO - 1708801323286 Marionette DEBUG 2 -> [0,12,"Marionette:SetContext",{"value":"content"}]
[task 2024-02-24T19:02:03.286Z] 19:02:03 INFO - 1708801323286 Marionette DEBUG 2 <- [1,12,null,{"value":null}]
[task 2024-02-24T19:02:03.287Z] 19:02:03 INFO - 1708801323287 Marionette DEBUG 2 -> [0,13,"Marionette:GetContext",{}]
[task 2024-02-24T19:02:03.287Z] 19:02:03 INFO - 1708801323287 Marionette DEBUG 2 <- [1,13,null,{"value":"content"}]
[task 2024-02-24T19:02:03.288Z] 19:02:03 INFO - 1708801323288 Marionette DEBUG 2 -> [0,14,"WebDriver:DeleteSession",{}]
[task 2024-02-24T19:02:03.289Z] 19:02:03 INFO - 1708801323289 Marionette TRACE [1] MarionetteCommands actor destroyed for window id 2
[task 2024-02-24T19:02:03.291Z] 19:02:03 INFO - 1708801323291 Marionette DEBUG 2 <- [1,14,null,{"value":null}]
[task 2024-02-24T19:02:03.332Z] 19:02:03 INFO - Application command: /builds/worker/workspace/build/application/firefox/firefox -no-remote -marionette -profile /tmp/tmptybb_9wz.mozrunner
[task 2024-02-24T19:02:03.725Z] 19:02:03 INFO - Inconsistency detected by ld.so: ../elf/dl-tls.c: 481: _dl_allocate_tls_init: Assertion `listp->slotinfo[cnt].gen <= GL(dl_tls_generation)' failed!
[task 2024-02-24T19:02:03.847Z] 19:02:03 INFO - TEST-UNEXPECTED-ERROR | testing/marionette/harness/marionette_harness/tests/unit/test_quit_restart.py TestQuitRestart.test_force_restart | OSError: Process has been unexpectedly closed (Exit code: 127) (Reason: Timed out waiting for connection on 127.0.0.1:2828!)
[task 2024-02-24T19:02:03.847Z] 19:02:03 INFO - Traceback (most recent call last):
[task 2024-02-24T19:02:03.847Z] 19:02:03 INFO - File "/builds/worker/workspace/build/venv/lib/python3.8/site-packages/marionette_harness/marionette_test/testcases.py", line 198, in run
[task 2024-02-24T19:02:03.847Z] 19:02:03 INFO - testMethod()
[task 2024-02-24T19:02:03.848Z] 19:02:03 INFO - File "/builds/worker/workspace/build/tests/marionette/tests/testing/marionette/harness/marionette_harness/tests/unit/test_quit_restart.py", line 132, in test_force_restart
[task 2024-02-24T19:02:03.848Z] 19:02:03 INFO - self.marionette.restart(in_app=False)
[task 2024-02-24T19:02:03.848Z] 19:02:03 INFO - File "/builds/worker/workspace/build/venv/lib/python3.8/site-packages/marionette_driver/decorators.py", line 34, in _
[task 2024-02-24T19:02:03.849Z] 19:02:03 INFO - m._handle_socket_failure()
[task 2024-02-24T19:02:03.849Z] 19:02:03 INFO - File "/builds/worker/workspace/build/venv/lib/python3.8/site-packages/marionette_driver/marionette.py", line 853, in _handle_socket_failure
[task 2024-02-24T19:02:03.850Z] 19:02:03 INFO - reraise(
[task 2024-02-24T19:02:03.850Z] 19:02:03 INFO - File "/builds/worker/workspace/build/venv/lib/python3.8/site-packages/six.py", line 702, in reraise
[task 2024-02-24T19:02:03.850Z] 19:02:03 INFO - raise value.with_traceback(tb)
[task 2024-02-24T19:02:03.850Z] 19:02:03 INFO - File "/builds/worker/workspace/build/venv/lib/python3.8/site-packages/marionette_driver/decorators.py", line 24, in _
[task 2024-02-24T19:02:03.850Z] 19:02:03 INFO - return func(*args, **kwargs)
[task 2024-02-24T19:02:03.850Z] 19:02:03 INFO - File "/builds/worker/workspace/build/venv/lib/python3.8/site-packages/marionette_driver/marionette.py", line 1302, in restart
[task 2024-02-24T19:02:03.850Z] 19:02:03 INFO - self.raise_for_port(timeout=self.DEFAULT_STARTUP_TIMEOUT)
[task 2024-02-24T19:02:03.851Z] 19:02:03 INFO - File "/builds/worker/workspace/build/venv/lib/python3.8/site-packages/marionette_driver/marionette.py", line 744, in raise_for_port
[task 2024-02-24T19:02:03.851Z] 19:02:03 INFO - raise socket.timeout(
[task 2024-02-24T19:02:03.851Z] 19:02:03 INFO - TEST-INFO took 625ms
[task 2024-02-24T19:02:03.852Z] 19:02:03 INFO - Application command: /builds/worker/workspace/build/application/firefox/firefox -no-remote -marionette -profile /tmp/tmptybb_9wz.mozrunner
[task 2024-02-24T19:02:04.205Z] 19:02:04 INFO - ATTENTION: default value of option mesa_glthread overridden by environment.
[task 2024-02-24T19:02:04.236Z] 19:02:04 INFO - 1708801324236 Marionette INFO Marionette enabled
[task 2024-02-24T19:02:04.240Z] 19:02:04 INFO - 1708801324239 Marionette TRACE Received observer notification final-ui-startup
[task 2024-02-24T19:02:04.291Z] 19:02:04 INFO - ATTENTION: default value of option mesa_glthread overridden by environment.
[task 2024-02-24T19:02:04.313Z] 19:02:04 INFO - 1708801324313 Marionette INFO Listening on port 2828
[task 2024-02-24T19:02:04.315Z] 19:02:04 INFO - 1708801324313 Marionette DEBUG Marionette is listening
[task 2024-02-24T19:02:04.330Z] 19:02:04 INFO - 1708801324330 Marionette DEBUG Accepted connection 0 from 127.0.0.1:58468
[task 2024-02-24T19:02:04.339Z] 19:02:04 INFO - 1708801324339 Marionette DEBUG Closed connection 0
[task 2024-02-24T19:02:04.340Z] 19:02:04 INFO - 1708801324339 Marionette DEBUG Accepted connection 1 from 127.0.0.1:58470
[task 2024-02-24T19:02:04.453Z] 19:02:04 INFO - 1708801324453 Marionette DEBUG 1 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
[task 2024-02-24T19:02:04.457Z] 19:02:04 INFO - 1708801324457 Marionette DEBUG Waiting for initial application window
[task 2024-02-24T19:02:07.463Z] 19:02:07 INFO - console.error: ({})
[task 2024-02-24T19:02:07.489Z] 19:02:07 INFO - console.error: ({})
[task 2024-02-24T19:02:08.069Z] 19:02:08 INFO - 1708801328069 Marionette TRACE Received observer notification browser-idle-startup-tasks-finished
[task 2024-02-24T19:02:08.078Z] 19:02:08 INFO - 1708801328077 RemoteAgent TRACE [3] ProgressListener Start: expectNavigation=false resolveWhenStarted=false unloadTimeout=5000 waitForExplicitStart=false
[task 2024-02-24T19:02:08.079Z] 19:02:08 INFO - 1708801328079 RemoteAgent TRACE [3] ProgressListener Setting unload timer (5000ms)
[task 2024-02-24T19:02:08.080Z] 19:02:08 INFO - 1708801328080 RemoteAgent TRACE [3] Document already finished loading: about:blank
[task 2024-02-24T19:02:08.081Z] 19:02:08 INFO - 1708801328080 RemoteAgent TRACE [3] ProgressListener Stop: has error=false
[task 2024-02-24T19:02:08.095Z] 19:02:08 INFO - 1708801328094 Marionette DEBUG 1 <- [1,1,null,{"sessionId":"f0f6a106-7fab-4657-87a6-d9b508632b9a","capabilities":{"browserName":"firefox","browserVersion":"125.0a1","platformName":"linux","acceptInsecureCerts":false,"pageLoadStrategy":"normal","setWindowRect":true,"timeouts":{"implicit":0,"pageLoad":300000,"script":30000},"strictFileInteractability":true,"unhandledPromptBehavior":"dismiss and notify","moz:accessibilityChecks":false,"moz:buildID":"20240224181508","moz:headless":false,"moz:platformVersion":"4.4.0-1014-aws","moz:processID":23185,"moz:profile":"/tmp/tmptybb_9wz.mozrunner","moz:shutdownTimeout":60000,"moz:webdriverClick":true,"moz:windowless":false,"proxy":{}}}]
[task 2024-02-24T19:02:08.115Z] 19:02:08 INFO - 1708801328113 Marionette DEBUG 1 -> [0,2,"Marionette:GetContext",{}]
[task 2024-02-24T19:02:08.115Z] 19:02:08 INFO - 1708801328114 Marionette DEBUG 1 <- [1,2,null,{"value":"content"}]
[task 2024-02-24T19:02:08.122Z] 19:02:08 INFO - 1708801328122 Marionette DEBUG 1 -> [0,3,"Marionette:SetContext",{"value":"chrome"}]
[task 2024-02-24T19:02:08.124Z] 19:02:08 INFO - 1708801328123 Marionette DEBUG 1 <- [1,3,null,{"value":null}]
[task 2024-02-24T19:02:08.126Z] 19:02:08 INFO - 1708801328126 Marionette DEBUG 1 -> [0,4,"WebDriver:ExecuteScript",{"script":"const { Preferences } = ChromeUtils.importESModule(\n \"resource://gre/modules/Preferences.sys.mjs\"\n );\n Preferences.reset(arguments[0]);","args":["startup.homepage_welcome_url"],"newSandbox":true,"sandbox":"default","line":878,"filename":"../../venv/lib/python3.8/site-packages/marionette_driver/marionette.py"}]
[task 2024-02-24T19:02:08.134Z] 19:02:08 INFO - 1708801328134 RemoteAgent TRACE WebDriverProcessData actor created for PID 23185
[task 2024-02-24T19:02:08.137Z] 19:02:08 INFO - 1708801328136 Marionette TRACE [1] MarionetteCommands actor created for window id 2
[task 2024-02-24T19:02:08.147Z] 19:02:08 INFO - 1708801328147 Marionette DEBUG 1 <- [1,4,null,{"value":null}]
[task 2024-02-24T19:02:08.152Z] 19:02:08 INFO - 1708801328151 Marionette DEBUG 1 -> [0,5,"Marionette:SetContext",{"value":"content"}]
[task 2024-02-24T19:02:08.153Z] 19:02:08 INFO - 1708801328153 Marionette DEBUG 1 <- [1,5,null,{"value":null}]
[task 2024-02-24T19:02:08.157Z] 19:02:08 INFO - 1708801328157 Marionette DEBUG 1 -> [0,6,"WebDriver:DeleteSession",{}]
[task 2024-02-24T19:02:08.158Z] 19:02:08 INFO - 1708801328158 Marionette TRACE [1] MarionetteCommands actor destroyed for window id 2
[task 2024-02-24T19:02:08.165Z] 19:02:08 INFO - 1708801328164 Marionette DEBUG 1 <- [1,6,null,{"value":null}]
[task 2024-02-24T19:02:08.178Z] 19:02:08 INFO - TEST-START | testing/marionette/harness/marionette_harness/tests/unit/test_quit_restart.py TestQuitRestart.test_in_app_quit
| Comment hidden (Intermittent Failures Robot) |
|
||
Comment 2•2 years ago
|
||
The reported failure here is actually bug 1819763.
Status: NEW → RESOLVED
Closed: 2 years ago
Resolution: --- → INCOMPLETE
You need to log in
before you can comment on or make changes to this bug.
Description
•