Closed
Bug 1815450
Opened 2 years ago
Closed 2 years ago
Intermittent TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/element_click/navigate.py | expected OK
Categories
(Remote Protocol :: Marionette, defect, P5)
Remote Protocol
Marionette
Tracking
(Not tracked)
RESOLVED
DUPLICATE
of bug 1630162
People
(Reporter: intermittent-bug-filer, Unassigned)
Details
(Keywords: intermittent-failure)
Filed by: chorotan [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=404867034&repo=try
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/dYQQLbJIRQ62MlJAgQtIvw/runs/0/artifacts/public/logs/live_backing.log
ask 2023-02-07T11:47:10.383Z] 11:47:10 INFO - STDOUT: tests/web-platform/tests/webdriver/tests/element_click/navigate.py::test_link_closes_window
[task 2023-02-07T11:47:10.384Z] 11:47:10 INFO - PID 4351 | 1675770430382 webdriver::server DEBUG -> DELETE /session/232240bb-853f-4e44-9e99-feef0ac4c21b
[task 2023-02-07T11:47:10.452Z] 11:47:10 INFO - PID 4351 | 1675770430451 Marionette DEBUG 0 -> [0,23,"Marionette:Quit",{"flags":["eForceQuit"]}]
[task 2023-02-07T11:47:10.454Z] 11:47:10 INFO - PID 4351 | 1675770430452 Marionette INFO Stopped listening on port 35478
[task 2023-02-07T11:47:10.458Z] 11:47:10 INFO - PID 4351 | 1675770430456 Marionette TRACE [12] MarionetteCommands actor destroyed for window id 10737418241
[task 2023-02-07T11:47:10.847Z] 11:47:10 INFO - PID 4351 | 1675770430846 Marionette TRACE Received observer notification quit-application
[task 2023-02-07T11:47:10.855Z] 11:47:10 INFO - PID 4351 | 1675770430854 Marionette TRACE Received observer notification quit-application
[task 2023-02-07T11:47:10.858Z] 11:47:10 INFO - PID 4351 | 1675770430856 Marionette DEBUG Marionette stopped listening
[task 2023-02-07T11:47:10.863Z] 11:47:10 INFO - PID 4351 | 1675770430862 Marionette DEBUG 0 <- [1,23,null,{"cause":"shutdown","forced":false,"in_app":true}]
[task 2023-02-07T11:47:11.082Z] 11:47:11 INFO - PID 4351 | 1675770431081 webdriver::server DEBUG Teardown session
[task 2023-02-07T11:47:11.102Z] 11:47:11 INFO - PID 4351 | 1675770431101 Marionette DEBUG Closed connection 0
[task 2023-02-07T11:47:11.629Z] 11:47:11 INFO - PID 4351 | console.error: (new TypeError("NetworkError: Network request failed", "resource://services-settings/Utils.jsm", 237))
[task 2023-02-07T11:47:11.632Z] 11:47:11 INFO - PID 4351 | JavaScript error: resource://services-settings/Utils.jsm, line 237: TypeError: NetworkError: Network request failed
[task 2023-02-07T11:47:11.822Z] 11:47:11 INFO - PID 4351 | WARNING: A blocker encountered an error while we were waiting.
[task 2023-02-07T11:47:11.822Z] 11:47:11 INFO - PID 4351 | Blocker: Waiting for ping task
[task 2023-02-07T11:47:11.824Z] 11:47:11 INFO - PID 4351 | Phase: TelemetryController: Waiting for pending ping activity
[task 2023-02-07T11:47:11.825Z] 11:47:11 INFO - PID 4351 | State: (none)
[task 2023-02-07T11:47:11.826Z] 11:47:11 INFO - PID 4351 | WARNING: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange"
[task 2023-02-07T11:47:11.826Z] 11:47:11 INFO - PID 4351 | WARNING: addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:727:15
[task 2023-02-07T11:47:11.830Z] 11:47:11 INFO - PID 4351 | addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:523:26
[task 2023-02-07T11:47:11.830Z] 11:47:11 INFO - PID 4351 | addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:458:15
[task 2023-02-07T11:47:11.830Z] 11:47:11 INFO - PID 4351 | setupShutdown@resource://gre/modules/osfile/osfile_async_front.jsm:1548:28
[task 2023-02-07T11:47:11.830Z] 11:47:11 INFO - PID 4351 | @resource://gre/modules/osfile/osfile_async_front.jsm:1568:16
[task 2023-02-07T11:47:11.830Z] 11:47:11 INFO - PID 4351 | @resource://gre/modules/osfile.jsm:12:30
[task 2023-02-07T11:47:11.831Z] 11:47:11 INFO - PID 4351 | @resource://gre/modules/TelemetryStorage.sys.mjs:10:28
[task 2023-02-07T11:47:11.831Z] 11:47:11 INFO - PID 4351 | _checkPendingPings@resource://gre/modules/TelemetrySend.sys.mjs:863:17
[task 2023-02-07T11:47:11.831Z] 11:47:11 INFO - PID 4351 | setup@resource://gre/modules/TelemetrySend.sys.mjs:803:18
[task 2023-02-07T11:47:11.831Z] 11:47:11 INFO - PID 4351 | setup@resource://gre/modules/TelemetrySend.sys.mjs:241:30
[task 2023-02-07T11:47:11.831Z] 11:47:11 INFO - PID 4351 | setupTelemetry/this._delayedInitTask<@resource://gre/modules/TelemetryControllerParent.sys.mjs:828:36
[task 2023-02-07T11:47:11.832Z] 11:47:11 INFO - PID 4351 | observe@resource://gre/modules/AsyncShutdown.sys.mjs:576:16
[task 2023-02-07T11:47:11.849Z] 11:47:11 INFO - PID 4351 | console.error: "TelemetryScheduler.shutdown - Already shut down"
[task 2023-02-07T11:47:11.939Z] 11:47:11 INFO - PID 4351 | WARNING: A blocker encountered an error while we were waiting.
[task 2023-02-07T11:47:11.941Z] 11:47:11 INFO - PID 4351 | Blocker: Waiting for ping task
[task 2023-02-07T11:47:11.943Z] 11:47:11 INFO - PID 4351 | Phase: TelemetryController: Waiting for pending ping activity
[task 2023-02-07T11:47:11.944Z] 11:47:11 INFO - PID 4351 | State: (none)
[task 2023-02-07T11:47:11.944Z] 11:47:11 INFO - PID 4351 | WARNING: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange"
[task 2023-02-07T11:47:11.944Z] 11:47:11 INFO - PID 4351 | WARNING: addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:727:15
[task 2023-02-07T11:47:11.945Z] 11:47:11 INFO - PID 4351 | addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:523:26
[task 2023-02-07T11:47:11.946Z] 11:47:11 INFO - PID 4351 | addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:458:15
[task 2023-02-07T11:47:11.946Z] 11:47:11 INFO - PID 4351 | setupShutdown@resource://gre/modules/osfile/osfile_async_front.jsm:1548:28
[task 2023-02-07T11:47:11.947Z] 11:47:11 INFO - PID 4351 | @resource://gre/modules/osfile/osfile_async_front.jsm:1568:16
[task 2023-02-07T11:47:11.948Z] 11:47:11 INFO - PID 4351 | @resource://gre/modules/osfile.jsm:12:30
[task 2023-02-07T11:47:11.949Z] 11:47:11 INFO - PID 4351 | @resource://gre/modules/TelemetryStorage.sys.mjs:10:28
[task 2023-02-07T11:47:11.950Z] 11:47:11 INFO - PID 4351 | _checkPendingPings@resource://gre/modules/TelemetrySend.sys.mjs:863:17
[task 2023-02-07T11:47:11.950Z] 11:47:11 INFO - PID 4351 | setup@resource://gre/modules/TelemetrySend.sys.mjs:803:18
[task 2023-02-07T11:47:11.951Z] 11:47:11 INFO - PID 4351 | setup@resource://gre/modules/TelemetrySend.sys.mjs:241:30
[task 2023-02-07T11:47:11.952Z] 11:47:11 INFO - PID 4351 | setupTelemetry/this._delayedInitTask<@resource://gre/modules/TelemetryControllerParent.sys.mjs:828:36
[task 2023-02-07T11:47:11.953Z] 11:47:11 INFO - PID 4351 | observe@resource://gre/modules/AsyncShutdown.sys.mjs:576:16
[task 2023-02-07T11:47:11.958Z] 11:47:11 INFO - PID 4351 | WARNING: A blocker encountered an error while we were waiting.
[task 2023-02-07T11:47:11.958Z] 11:47:11 INFO - PID 4351 | Blocker: TelemetryController: shutting down
[task 2023-02-07T11:47:11.958Z] 11:47:11 INFO - PID 4351 | Phase: profile-before-change-telemetry
[task 2023-02-07T11:47:11.958Z] 11:47:11 INFO - PID 4351 | State: Error getting state: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange" at addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:727:15
[task 2023-02-07T11:47:11.959Z] 11:47:11 INFO - PID 4351 | addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:523:26
[task 2023-02-07T11:47:11.959Z] 11:47:11 INFO - PID 4351 | addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:458:15
[task 2023-02-07T11:47:11.959Z] 11:47:11 INFO - PID 4351 | setupShutdown@resource://gre/modules/osfile/osfile_async_front.jsm:1548:28
[task 2023-02-07T11:47:11.959Z] 11:47:11 INFO - PID 4351 | @resource://gre/modules/osfile/osfile_async_front.jsm:1568:16
[task 2023-02-07T11:47:11.959Z] 11:47:11 INFO - PID 4351 | @resource://gre/modules/osfile.jsm:12:30
[task 2023-02-07T11:47:11.959Z] 11:47:11 INFO - PID 4351 | @resource://gre/modules/TelemetryStorage.sys.mjs:10:28
[task 2023-02-07T11:47:11.960Z] 11:47:11 INFO - PID 4351 | _checkPendingPings@resource://gre/modules/TelemetrySend.sys.mjs:863:17
[task 2023-02-07T11:47:11.960Z] 11:47:11 INFO - PID 4351 | setup@resource://gre/modules/TelemetrySend.sys.mjs:803:18
[task 2023-02-07T11:47:11.960Z] 11:47:11 INFO - PID 4351 | setup@resource://gre/modules/TelemetrySend.sys.mjs:241:30
[task 2023-02-07T11:47:11.960Z] 11:47:11 INFO - PID 4351 | setupTelemetry/this._delayedInitTask<@resource://gre/modules/TelemetryControllerParent.sys.mjs:828:36
[task 2023-02-07T11:47:11.960Z] 11:47:11 INFO - PID 4351 | observe@resource://gre/modules/AsyncShutdown.sys.mjs:576:16
[task 2023-02-07T11:47:11.961Z] 11:47:11 INFO - PID 4351 | WARNING: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange"
[task 2023-02-07T11:47:11.961Z] 11:47:11 INFO - PID 4351 | WARNING: addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:727:15
[task 2023-02-07T11:47:11.961Z] 11:47:11 INFO - PID 4351 | addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:523:26
[task 2023-02-07T11:47:11.964Z] 11:47:11 INFO - PID 4351 | addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:458:15
[task 2023-02-07T11:47:11.964Z] 11:47:11 INFO - PID 4351 | setupShutdown@resource://gre/modules/osfile/osfile_async_front.jsm:1548:28
[task 2023-02-07T11:47:11.964Z] 11:47:11 INFO - PID 4351 | @resource://gre/modules/osfile/osfile_async_front.jsm:1568:16
[task 2023-02-07T11:47:11.964Z] 11:47:11 INFO - PID 4351 | @resource://gre/modules/osfile.jsm:12:30
[task 2023-02-07T11:47:11.964Z] 11:47:11 INFO - PID 4351 | @resource://gre/modules/TelemetryStorage.sys.mjs:10:28
[task 2023-02-07T11:47:11.964Z] 11:47:11 INFO - PID 4351 | _checkPendingPings@resource://gre/modules/TelemetrySend.sys.mjs:863:17
[task 2023-02-07T11:47:11.964Z] 11:47:11 INFO - PID 4351 | setup@resource://gre/modules/TelemetrySend.sys.mjs:803:18
[task 2023-02-07T11:47:11.965Z] 11:47:11 INFO - PID 4351 | setup@resource://gre/modules/TelemetrySend.sys.mjs:241:30
[task 2023-02-07T11:47:11.966Z] 11:47:11 INFO - PID 4351 | setupTelemetry/this._delayedInitTask<@resource://gre/modules/TelemetryControllerParent.sys.mjs:828:36
[task 2023-02-07T11:47:11.968Z] 11:47:11 INFO - PID 4351 | observe@resource://gre/modules/AsyncShutdown.sys.mjs:576:16
[task 2023-02-07T11:47:11.969Z] 11:47:11 INFO - PID 4351 | JavaScript error: resource://gre/modules/AsyncShutdown.sys.mjs, line 727: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange"
[task 2023-02-07T11:47:11.970Z] 11:47:11 INFO - PID 4351 | JavaScript error: resource://gre/modules/AsyncShutdown.sys.mjs, line 727: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange"
[task 2023-02-07T11:47:11.971Z] 11:47:11 INFO - PID 4351 | JavaScript error: resource://gre/modules/AsyncShutdown.sys.mjs, line 727: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange"
[task 2023-02-07T11:47:11.971Z] 11:47:11 INFO - PID 4351 | JavaScript error: resource://gre/modules/AsyncShutdown.sys.mjs, line 727: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange"
[task 2023-02-07T11:47:11.972Z] 11:47:11 INFO - PID 4351 | JavaScript error: resource://gre/modules/AsyncShutdown.sys.mjs, line 727: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange"
[task 2023-02-07T11:47:14.587Z] 11:47:14 INFO - PID 4351 | 1675770434585 geckodriver::browser DEBUG Browser process stopped: exit status: 0
[task 2023-02-07T11:47:14.587Z] 11:47:14 INFO - PID 4351 | 1675770434586 webdriver::server DEBUG <- 200 OK {"value":null}
[task 2023-02-07T11:47:14.589Z] 11:47:14 INFO - PID 4351 | 1675770434587 webdriver::server DEBUG -> POST /session {"capabilities": {"alwaysMatch": {"moz:firefoxOptions": {"args": ["--profile", "/tmp/tmp3y0nsgj8.mozrunner"], "binary": "/builds/worker/workspace/build/application/firefox/firefox"}}}}
[task 2023-02-07T11:47:14.590Z] 11:47:14 INFO - PID 4351 | 1675770434587 geckodriver::capabilities DEBUG Trying to read firefox version from ini files
[task 2023-02-07T11:47:14.590Z] 11:47:14 INFO - PID 4351 | 1675770434588 geckodriver::capabilities DEBUG Found version 111.0
[task 2023-02-07T11:47:14.591Z] 11:47:14 INFO - PID 4351 | 1675770434588 geckodriver::browser DEBUG Backing up prefs to "/tmp/tmp3y0nsgj8.mozrunner/user.geckodriver_backup"
[task 2023-02-07T11:47:14.596Z] 11:47:14 INFO - PID 4351 | 1675770434595 mozrunner::runner INFO Running command: "/builds/worker/workspace/build/application/firefox/firefox" "--marionette" "--profile" "/tmp/tmp3y0nsgj8.mozrunner" "-no-remote"
[task 2023-02-07T11:47:14.597Z] 11:47:14 INFO - PID 4351 | 1675770434595 geckodriver::marionette DEBUG Waiting 60s to connect to browser on 127.0.0.1
[task 2023-02-07T11:47:14.598Z] 11:47:14 INFO - PID 4351 | 1675770434595 geckodriver::browser TRACE Failed to open /tmp/tmp3y0nsgj8.mozrunner/MarionetteActivePort
[task 2023-02-07T11:47:14.599Z] 11:47:14 INFO - PID 4351 | 1675770434595 geckodriver::marionette TRACE Retrying in 100ms
[task 2023-02-07T11:47:14.697Z] 11:47:14 INFO - PID 4351 | 1675770434695 geckodriver::browser TRACE Failed to open /tmp/tmp3y0nsgj8.mozrunner/MarionetteActivePort
[task 2023-02-07T11:47:14.698Z] 11:47:14 INFO - PID 4351 | 1675770434695 geckodriver::marionette TRACE Retrying in 100ms
[task 2023-02-07T11:47:14.797Z] 11:47:14 INFO - PID 4351 | 1675770434795 geckodriver::browser TRACE Failed to open /tmp/tmp3y0nsgj8.mozrunner/MarionetteActivePort
[task 2023-02-07T11:47:14.798Z] 11:47:14 INFO - PID 4351 | 1675770434795 geckodriver::marionette TRACE Retrying in 100ms
[task 2023-02-07T11:47:14.898Z] 11:47:14 INFO - PID 4351 | 1675770434896 geckodriver::browser TRACE Failed to open /tmp/tmp3y0nsgj8.mozrunner/MarionetteActivePort
[task 2023-02-07T11:47:14.899Z] 11:47:14 INFO - PID 4351 | 1675770434896 geckodriver::marionette TRACE Retrying in 100ms
[task 2023-02-07T11:47:14.998Z] 11:47:14 INFO - PID 4351 | 1675770434996 geckodriver::browser TRACE Failed to open /tmp/tmp3y0nsgj8.mozrunner/MarionetteActivePort
[task 2023-02-07T11:47:14.999Z] 11:47:14 INFO - PID 4351 | 1675770434996 geckodriver::marionette TRACE Retrying in 100ms
[task 2023-02-07T11:47:15.101Z] 11:47:15 INFO - PID 4351 | 1675770435096 geckodriver::browser TRACE Failed to open /tmp/tmp3y0nsgj8.mozrunner/MarionetteActivePort
[task 2023-02-07T11:47:15.102Z] 11:47:15 INFO - PID 4351 | 1675770435096 geckodriver::marionette TRACE Retrying in 100ms
[task 2023-02-07T11:47:15.142Z] 11:47:15 INFO - PID 4351 | console.warn: services.settings: Ignoring preference override of remote settings server
[task 2023-02-07T11:47:15.143Z] 11:47:15 INFO - PID 4351 | console.warn: services.settings: Allow by setting MOZ_REMOTE_SETTINGS_DEVTOOLS=1 in the environment
[task 2023-02-07T11:47:15.198Z] 11:47:15 INFO - PID 4351 | 1675770435196 geckodriver::browser TRACE Failed to open /tmp/tmp3y0nsgj8.mozrunner/MarionetteActivePort
[task 2023-02-07T11:47:15.200Z] 11:47:15 INFO - PID 4351 | 1675770435196 geckodriver::marionette TRACE Retrying in 100ms
[task 2023-02-07T11:47:15.298Z] 11:47:15 INFO - PID 4351 | 1675770435296 geckodriver::browser TRACE Failed to open /tmp/tmp3y0nsgj8.mozrunner/MarionetteActivePort
[task 2023-02-07T11:47:15.299Z] 11:47:15 INFO - PID 4351 | 1675770435296 geckodriver::marionette TRACE Retrying in 100ms
[task 2023-02-07T11:47:15.398Z] 11:47:15 INFO - PID 4351 | 1675770435397 geckodriver::browser TRACE Failed to open /tmp/tmp3y0nsgj8.mozrunner/MarionetteActivePort
[task 2023-02-07T11:47:15.399Z] 11:47:15 INFO - PID 4351 | 1675770435397 geckodriver::marionette TRACE Retrying in 100ms
[task 2023-02-07T11:47:15.498Z] 11:47:15 INFO - PID 4351 | 1675770435497 geckodriver::browser TRACE Failed to open /tmp/tmp3y0nsgj8.mozrunner/MarionetteActivePort
[task 2023-02-07T11:47:15.499Z] 11:47:15 INFO - PID 4351 | 1675770435497 geckodriver::marionette TRACE Retrying in 100ms
[task 2023-02-07T11:47:15.598Z] 11:47:15 INFO - PID 4351 | 1675770435597 geckodriver::browser TRACE Failed to open /tmp/tmp3y0nsgj8.mozrunner/MarionetteActivePort
[task 2023-02-07T11:47:15.599Z] 11:47:15 INFO - PID 4351 | 1675770435597 geckodriver::marionette TRACE Retrying in 100ms
[task 2023-02-07T11:47:15.699Z] 11:47:15 INFO - PID 4351 | 1675770435697 geckodriver::browser TRACE Failed to open /tmp/tmp3y0nsgj8.mozrunner/MarionetteActivePort
[task 2023-02-07T11:47:15.700Z] 11:47:15 INFO - PID 4351 | 1675770435697 geckodriver::marionette TRACE Retrying in 100ms
[task 2023-02-07T11:47:15.799Z] 11:47:15 INFO - PID 4351 | 1675770435797 geckodriver::browser TRACE Failed to open /tmp/tmp3y0nsgj8.mozrunner/MarionetteActivePort
[task 2023-02-07T11:47:15.799Z] 11:47:15 INFO - PID 4351 | 1675770435797 geckodriver::marionette TRACE Retrying in 100ms
[task 2023-02-07T11:47:15.899Z] 11:47:15 INFO - PID 4351 | 1675770435898 geckodriver::browser TRACE Failed to open /tmp/tmp3y0nsgj8.mozrunner/MarionetteActivePort
[task 2023-02-07T11:47:15.900Z] 11:47:15 INFO - PID 4351 | 1675770435898 geckodriver::marionette TRACE Retrying in 100ms
[task 2023-02-07T11:47:15.999Z] 11:47:15 INFO - PID 4351 | 1675770435998 geckodriver::browser TRACE Failed to open /tmp/tmp3y0nsgj8.mozrunner/MarionetteActivePort
[task 2023-02-07T11:47:16.000Z] 11:47:16 INFO - PID 4351 | 1675770435998 geckodriver::marionette TRACE Retrying in 100ms
[task 2023-02-07T11:47:16.099Z] 11:47:16 INFO - PID 4351 | 1675770436098 geckodriver::browser TRACE Failed to open /tmp/tmp3y0nsgj8.mozrunner/MarionetteActivePort
[task 2023-02-07T11:47:16.101Z] 11:47:16 INFO - PID 4351 | 1675770436098 geckodriver::marionette TRACE Retrying in 100ms
[task 2023-02-07T11:47:16.200Z] 11:47:16 INFO - PID 4351 | 1675770436198 geckodriver::browser TRACE Failed to open /tmp/tmp3y0nsgj8.mozrunner/MarionetteActivePort
[task 2023-02-07T11:47:16.200Z] 11:47:16 INFO - PID 4351 | 1675770436198 geckodriver::marionette TRACE Retrying in 100ms
[task 2023-02-07T11:47:16.300Z] 11:47:16 INFO - PID 4351 | 1675770436299 geckodriver::browser TRACE Failed to open /tmp/tmp3y0nsgj8.mozrunner/MarionetteActivePort
[task 2023-02-07T11:47:16.301Z] 11:47:16 INFO - PID 4351 | 1675770436299 geckodriver::marionette TRACE Retrying in 100ms
[task 2023-02-07T11:47:16.400Z] 11:47:16 INFO - PID 4351 | 1675770436399 geckodriver::browser TRACE Failed to open /tmp/tmp3y0nsgj8.mozrunner/MarionetteActivePort
[task 2023-02-07T11:47:16.402Z] 11:47:16 INFO - PID 4351 | 1675770436399 geckodriver::marionette TRACE Retrying in 100ms
[task 2023-02-07T11:47:16.497Z] 11:47:16 INFO - PID 4351 | 1675770436496 Marionette INFO Marionette enabled
[task 2023-02-07T11:47:16.500Z] 11:47:16 INFO - PID 4351 | 1675770436499 geckodriver::browser TRACE Failed to open /tmp/tmp3y0nsgj8.mozrunner/MarionetteActivePort
[task 2023-02-07T11:47:16.501Z] 11:47:16 INFO - PID 4351 | 1675770436499 geckodriver::marionette TRACE Retrying in 100ms
[task 2023-02-07T11:47:16.504Z] 11:47:16 INFO - PID 4351 | 1675770436502 Marionette TRACE Received observer notification final-ui-startup
[task 2023-02-07T11:47:16.511Z] 11:47:16 INFO - PID 4351 | 1675770436509 Marionette INFO Listening on port 33292
[task 2023-02-07T11:47:16.512Z] 11:47:16 INFO - PID 4351 | 1675770436511 Marionette DEBUG Marionette is listening
[task 2023-02-07T11:47:16.600Z] 11:47:16 INFO - PID 4351 | Read port: 33292
[task 2023-02-07T11:47:16.855Z] 11:47:16 INFO - PID 4351 | 1675770436854 Marionette DEBUG Accepted connection 0 from 127.0.0.1:45754
[task 2023-02-07T11:47:16.880Z] 11:47:16 INFO - PID 4351 | 1675770436876 geckodriver::marionette DEBUG Connection to Marionette established on 127.0.0.1:33292.
[task 2023-02-07T11:47:16.909Z] 11:47:16 INFO - PID 4351 | 1675770436908 Marionette DEBUG 0 -> [0,1,"WebDriver:NewSession",{}]
[task 2023-02-07T11:47:16.925Z] 11:47:16 INFO - PID 4351 | 1675770436924 Marionette DEBUG Waiting for initial application window
[task 2023-02-07T11:47:23.996Z] 11:47:23 INFO - PID 4351 | console.error: ({})
[task 2023-02-07T11:47:27.982Z] 11:47:27 INFO - TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/element_click/navigate.py | expected OK
[task 2023-02-07T11:47:27.983Z] 11:47:27 INFO - TEST-INFO took 80003ms
[task 2023-02-07T11:47:28.283Z] 11:47:28 INFO - Closing logging queue
[task 2023-02-07T11:47:28.283Z] 11:47:28 INFO - queue closed
[task 2023-02-07T11:47:28.297Z] 11:47:28 INFO - PID 7007 | 1675770448295 geckodriver INFO Listening on 127.0.0.1:60039
[task 2023-02-07T11:47:28.299Z] 11:47:28 INFO - Starting runner
[task 2023-02-07T11:47:28.595Z] 11:47:28 INFO - TEST-START | /webdriver/tests/element_click/scroll_into_view.py
[task 2023-02-07T11:47:28.892Z] 11:47:28 INFO - STDOUT: ============================= test session starts ==============================
[task 2023-02-07T11:47:28.894Z] 11:47:28 INFO - STDOUT: platform linux -- Python 3.6.9, pytest-7.0.1, pluggy-unknown -- /builds/worker/workspace/build/venv/bin/python
[task 2023-02-07T11:47:28.897Z] 11:47:28 INFO - STDOUT: rootdir: /builds/worker/workspace/build
[task 2023-02-07T11:47:28.897Z] 11:47:28 INFO - STDOUT: plugins: asyncio-0.14.0
[task 2023-02-07T11:47:28.899Z] 11:47:28 INFO - STDOUT: collecting ...
[task 2023-02-07T11:47:28.913Z] 11:47:28 INFO - STDOUT: collected 10 items
[task 2023-02-07T11:47:28.915Z] 11:47:28 INFO - STDOUT: tests/web-platform/tests/webdriver/tests/element_click/scroll_into_view.py::test_scroll_into_view
[task 2023-02-07T11:47:28.916Z] 11:47:28 INFO - PID 7007 | 1675770448915 webdriver::server DEBUG -> POST /session {"capabilities": {"alwaysMatch": {"moz:firefoxOptions": {"args": ["--profile", "/tmp/tmp3y0nsgj8.mozrunner"], "binary": "/builds/worker/workspace/build/application/firefox/firefox"}}}}
[task 2023-02-07T11:47:28.917Z] 11:47:28 INFO - PID 7007 | 1675770448915 geckodriver::capabilities DEBUG Trying to read firefox version from ini files
[task 2023-02-07T11:47:28.918Z] 11:47:28 INFO - PID 7007 | 1675770448916 geckodriver::capabilities DEBUG Found version 111.0
[task 2023-02-07T11:47:28.920Z] 11:47:28 INFO - PID 7007 | 1675770448916 geckodriver::browser DEBUG Backing up prefs to "/tmp/tmp3y0nsgj8.mozrunner/user.geckodriver_backup_1"
[task 2023-02-07T11:47:28.925Z] 11:47:28 INFO - PID 7007 | 1675770448923 mozrunner::runner INFO Running command: "/builds/worker/workspace/build/application/firefox/firefox" "--marionette" "--profile" "/tmp/tmp3y0nsgj8.mozrunner" "-no-remote"
|
||
Comment 1•2 years ago
|
||
Lets dupe to bug 1630162 given that we don't have that many of these timeouts for TSAN builds yet.
|
||
Comment 2•2 years ago
|
||
Moving bug to Remote Protocol::Marionette component per bug 1815831.
Component: geckodriver → Marionette
Product: Testing → Remote Protocol
You need to log in
before you can comment on or make changes to this bug.
Description
•