Closed
Bug 1800428
Opened 2 years ago
Closed 2 years ago
Intermittent mozilla/tests/webdriver/new_session/bidi_disabled.py | test_marionette_fallback_webdriver_session - ConnectionRefusedError: [Errno 111] Connection refused
Categories
(Remote Protocol :: Marionette, defect, P5)
Remote Protocol
Marionette
Tracking
(Not tracked)
RESOLVED
DUPLICATE
of bug 1571426
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=396012568&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/BcUcBnuqTdOmFy4NY2oVxw/runs/0/artifacts/public/logs/live_backing.log
[task 2022-11-09T05:08:46.619Z] 05:08:46 INFO - TEST-START | /_mozilla/webdriver/new_session/bidi_disabled.py
[task 2022-11-09T05:08:47.014Z] 05:08:47 INFO - STDOUT: ============================= test session starts ==============================
[task 2022-11-09T05:08:47.015Z] 05:08:47 INFO - STDOUT: platform linux -- Python 3.6.9, pytest-7.0.1, pluggy-unknown -- /builds/worker/workspace/build/venv/bin/python
[task 2022-11-09T05:08:47.017Z] 05:08:47 INFO - STDOUT: rootdir: /builds/worker/workspace/build
[task 2022-11-09T05:08:47.018Z] 05:08:47 INFO - STDOUT: plugins: asyncio-0.14.0
[task 2022-11-09T05:08:47.019Z] 05:08:47 INFO - STDOUT: collecting ...
[task 2022-11-09T05:08:47.024Z] 05:08:47 INFO - STDOUT: collected 1 item
[task 2022-11-09T05:08:47.024Z] 05:08:47 INFO - STDOUT: tests/web-platform/mozilla/tests/webdriver/new_session/bidi_disabled.py::test_marionette_fallback_webdriver_session
[task 2022-11-09T05:08:47.027Z] 05:08:47 INFO - STDOUT: Running command: ['/builds/worker/fetches/geckodriver', '--port', '38122', '-vv']
[task 2022-11-09T05:08:47.030Z] 05:08:47 INFO - STDOUT: 1667970527028 geckodriver INFO Listening on 127.0.0.1:38122
[task 2022-11-09T05:08:47.036Z] 05:08:47 INFO - STDOUT: 1667970527030 webdriver::server DEBUG -> POST /session {"capabilities": {"alwaysMatch": {"moz:firefoxOptions": {"args": ["--profile", "/tmp/tmpx1ngnk8k.mozrunner"] ... builds/worker/workspace/build/application/firefox/firefox", "prefs": {"remote.active-protocols": 2}}, "webSocketUrl": true}}}
[task 2022-11-09T05:08:47.036Z] 05:08:47 INFO - STDOUT: 1667970527030 geckodriver::capabilities DEBUG Trying to read firefox version from ini files
[task 2022-11-09T05:08:47.037Z] 05:08:47 INFO - STDOUT: 1667970527031 geckodriver::capabilities DEBUG Found version 108.0a1
[task 2022-11-09T05:08:47.039Z] 05:08:47 INFO - STDOUT: 1667970527031 geckodriver::browser DEBUG Backing up prefs to "/tmp/tmpx1ngnk8k.mozrunner/user.geckodriver_backup"
[task 2022-11-09T05:08:47.039Z] 05:08:47 INFO - STDOUT: 1667970527037 mozrunner::runner INFO Running command: "/builds/worker/workspace/build/application/firefox/firefox" "--marionette" "--profile" "/tmp/tmpx1ngnk8k.mozrunner" "--remote-debugging-port" "9222" "--remote-allow-hosts" "localhost" "-no-remote"
[task 2022-11-09T05:08:47.040Z] 05:08:47 INFO - STDOUT: 1667970527037 geckodriver::marionette DEBUG Waiting 60s to connect to browser on 127.0.0.1
[task 2022-11-09T05:08:47.041Z] 05:08:47 INFO - STDOUT: 1667970527037 geckodriver::browser TRACE Failed to open /tmp/tmpx1ngnk8k.mozrunner/MarionetteActivePort
[task 2022-11-09T05:08:47.041Z] 05:08:47 INFO - STDOUT: 1667970527037 geckodriver::marionette TRACE Retrying in 100ms
[task 2022-11-09T05:08:47.095Z] 05:08:47 INFO - STDOUT: [Parent 25048, Main Thread] WARNING: Rejected attempt to change type of pref extensions.formautofill.creditCards.available's user value from bool to string: file /builds/worker/checkouts/gecko/modules/libpref/Preferences.cpp:1789
[task 2022-11-09T05:08:47.139Z] 05:08:47 INFO - STDOUT: 1667970527138 geckodriver::browser TRACE Failed to open /tmp/tmpx1ngnk8k.mozrunner/MarionetteActivePort
[task 2022-11-09T05:08:47.140Z] 05:08:47 INFO - STDOUT: 1667970527138 geckodriver::marionette TRACE Retrying in 100ms
[task 2022-11-09T05:08:47.211Z] 05:08:47 INFO - STDOUT: [Parent 25048, Main Thread] WARNING: GLX_swap_control unsupported, ASAP mode may still block on buffer swaps.: file /builds/worker/checkouts/gecko/gfx/gl/GLContextProviderGLX.cpp:213
[task 2022-11-09T05:08:47.240Z] 05:08:47 INFO - STDOUT: 1667970527238 geckodriver::browser TRACE Failed to open /tmp/tmpx1ngnk8k.mozrunner/MarionetteActivePort
[task 2022-11-09T05:08:47.241Z] 05:08:47 INFO - STDOUT: 1667970527238 geckodriver::marionette TRACE Retrying in 100ms
[task 2022-11-09T05:08:47.340Z] 05:08:47 INFO - STDOUT: 1667970527338 geckodriver::browser TRACE Failed to open /tmp/tmpx1ngnk8k.mozrunner/MarionetteActivePort
[task 2022-11-09T05:08:47.341Z] 05:08:47 INFO - STDOUT: 1667970527338 geckodriver::marionette TRACE Retrying in 100ms
[task 2022-11-09T05:08:47.440Z] 05:08:47 INFO - STDOUT: 1667970527438 geckodriver::browser TRACE Failed to open /tmp/tmpx1ngnk8k.mozrunner/MarionetteActivePort
[task 2022-11-09T05:08:47.441Z] 05:08:47 INFO - STDOUT: 1667970527438 geckodriver::marionette TRACE Retrying in 100ms
[task 2022-11-09T05:08:47.540Z] 05:08:47 INFO - STDOUT: 1667970527538 geckodriver::browser TRACE Failed to open /tmp/tmpx1ngnk8k.mozrunner/MarionetteActivePort
[task 2022-11-09T05:08:47.541Z] 05:08:47 INFO - STDOUT: 1667970527538 geckodriver::marionette TRACE Retrying in 100ms
[task 2022-11-09T05:08:47.640Z] 05:08:47 INFO - STDOUT: 1667970527638 geckodriver::browser TRACE Failed to open /tmp/tmpx1ngnk8k.mozrunner/MarionetteActivePort
[task 2022-11-09T05:08:47.641Z] 05:08:47 INFO - STDOUT: 1667970527638 geckodriver::marionette TRACE Retrying in 100ms
[task 2022-11-09T05:08:47.740Z] 05:08:47 INFO - STDOUT: 1667970527739 geckodriver::browser TRACE Failed to open /tmp/tmpx1ngnk8k.mozrunner/MarionetteActivePort
[task 2022-11-09T05:08:47.741Z] 05:08:47 INFO - STDOUT: 1667970527739 geckodriver::marionette TRACE Retrying in 100ms
[task 2022-11-09T05:08:47.840Z] 05:08:47 INFO - STDOUT: 1667970527839 geckodriver::browser TRACE Failed to open /tmp/tmpx1ngnk8k.mozrunner/MarionetteActivePort
[task 2022-11-09T05:08:47.841Z] 05:08:47 INFO - STDOUT: 1667970527839 geckodriver::marionette TRACE Retrying in 100ms
[task 2022-11-09T05:08:47.940Z] 05:08:47 INFO - STDOUT: 1667970527939 geckodriver::browser TRACE Failed to open /tmp/tmpx1ngnk8k.mozrunner/MarionetteActivePort
[task 2022-11-09T05:08:47.941Z] 05:08:47 INFO - STDOUT: 1667970527939 geckodriver::marionette TRACE Retrying in 100ms
[task 2022-11-09T05:08:48.041Z] 05:08:48 INFO - STDOUT: 1667970528039 geckodriver::browser TRACE Failed to open /tmp/tmpx1ngnk8k.mozrunner/MarionetteActivePort
[task 2022-11-09T05:08:48.041Z] 05:08:48 INFO - STDOUT: 1667970528039 geckodriver::marionette TRACE Retrying in 100ms
[task 2022-11-09T05:08:48.141Z] 05:08:48 INFO - STDOUT: 1667970528139 geckodriver::browser TRACE Failed to open /tmp/tmpx1ngnk8k.mozrunner/MarionetteActivePort
[task 2022-11-09T05:08:48.142Z] 05:08:48 INFO - STDOUT: 1667970528139 geckodriver::marionette TRACE Retrying in 100ms
[task 2022-11-09T05:08:48.241Z] 05:08:48 INFO - STDOUT: 1667970528239 geckodriver::browser TRACE Failed to open /tmp/tmpx1ngnk8k.mozrunner/MarionetteActivePort
[task 2022-11-09T05:08:48.242Z] 05:08:48 INFO - STDOUT: 1667970528239 geckodriver::marionette TRACE Retrying in 100ms
[task 2022-11-09T05:08:48.342Z] 05:08:48 INFO - STDOUT: 1667970528339 geckodriver::browser TRACE Failed to open /tmp/tmpx1ngnk8k.mozrunner/MarionetteActivePort
[task 2022-11-09T05:08:48.342Z] 05:08:48 INFO - STDOUT: 1667970528340 geckodriver::marionette TRACE Retrying in 100ms
[task 2022-11-09T05:08:48.441Z] 05:08:48 INFO - STDOUT: 1667970528440 geckodriver::browser TRACE Failed to open /tmp/tmpx1ngnk8k.mozrunner/MarionetteActivePort
[task 2022-11-09T05:08:48.442Z] 05:08:48 INFO - STDOUT: 1667970528440 geckodriver::marionette TRACE Retrying in 100ms
[task 2022-11-09T05:08:48.542Z] 05:08:48 INFO - STDOUT: 1667970528540 geckodriver::browser TRACE Failed to open /tmp/tmpx1ngnk8k.mozrunner/MarionetteActivePort
[task 2022-11-09T05:08:48.543Z] 05:08:48 INFO - STDOUT: 1667970528540 geckodriver::marionette TRACE Retrying in 100ms
[task 2022-11-09T05:08:48.622Z] 05:08:48 INFO - STDOUT: 1667970528620 RemoteAgent DEBUG CDP enabled
[task 2022-11-09T05:08:48.623Z] 05:08:48 INFO - STDOUT: 1667970528621 Marionette INFO Marionette enabled
[task 2022-11-09T05:08:48.625Z] 05:08:48 INFO - STDOUT: 1667970528624 Marionette TRACE Received observer notification final-ui-startup
[task 2022-11-09T05:08:48.627Z] 05:08:48 INFO - STDOUT: 1667970528626 Marionette INFO Listening on port 37566
[task 2022-11-09T05:08:48.628Z] 05:08:48 INFO - STDOUT: 1667970528627 Marionette DEBUG Marionette is listening
[task 2022-11-09T05:08:48.629Z] 05:08:48 INFO - STDOUT: 1667970528628 RemoteAgent TRACE Received observer notification final-ui-startup
[task 2022-11-09T05:08:48.641Z] 05:08:48 INFO - STDOUT: Read port: 37566
[task 2022-11-09T05:08:48.700Z] 05:08:48 INFO - STDOUT: [GLX] window c00003 has VisualID 0x41
[task 2022-11-09T05:08:48.712Z] 05:08:48 INFO - STDOUT: GL_VENDOR: VMware, Inc.
[task 2022-11-09T05:08:48.713Z] 05:08:48 INFO - STDOUT: mVendor: VMware, Inc.
[task 2022-11-09T05:08:48.714Z] 05:08:48 INFO - STDOUT: GL_RENDERER: llvmpipe (LLVM 10.0.0, 256 bits)
[task 2022-11-09T05:08:48.715Z] 05:08:48 INFO - STDOUT: mRenderer: Unknown
[task 2022-11-09T05:08:48.716Z] 05:08:48 INFO - STDOUT: mIsMesa: 1
[task 2022-11-09T05:08:48.717Z] 05:08:48 INFO - STDOUT: [Parent 25048, Renderer] WARNING: robust_buffer_access_behavior marked as unsupported: file /builds/worker/checkouts/gecko/gfx/gl/GLContextFeatures.cpp:632
[task 2022-11-09T05:08:48.717Z] 05:08:48 INFO - STDOUT: [Parent 25048, Renderer] WARNING: Robustness supported, strategy is not LOSE_CONTEXT_ON_RESET!: file /builds/worker/checkouts/gecko/gfx/gl/GLContext.cpp:995
[task 2022-11-09T05:08:48.718Z] 05:08:48 INFO - STDOUT: [Parent 25048, Renderer] WARNING: robustness marked as unsupported: file /builds/worker/checkouts/gecko/gfx/gl/GLContextFeatures.cpp:632
[task 2022-11-09T05:08:48.719Z] 05:08:48 INFO - STDOUT: [2022-11-09T05:08:48Z WARN webrender::device::gl] Missing optimized shader source for gpu_cache_update
[task 2022-11-09T05:08:48.764Z] 05:08:48 INFO - STDOUT: [2022-11-09T05:08:48Z WARN webrender::device::gl] Cropping texture upload Box2D((0, 0), (0, 1)) to None
[task 2022-11-09T05:08:48.765Z] 05:08:48 INFO - STDOUT: [2022-11-09T05:08:48Z WARN webrender::device::gl] Cropping texture upload Box2D((0, 0), (0, 1)) to None
[task 2022-11-09T05:08:48.766Z] 05:08:48 INFO - STDOUT: [2022-11-09T05:08:48Z WARN webrender::device::gl] Cropping texture upload Box2D((0, 0), (0, 1)) to None
[task 2022-11-09T05:08:48.780Z] 05:08:48 INFO - STDOUT: 1667970528779 RemoteAgent TRACE Available local IP addresses: 127.0.0.1, [::1]
[task 2022-11-09T05:08:48.789Z] 05:08:48 INFO - STDOUT: 1667970528788 CDP DEBUG Waiting for initial application window
[task 2022-11-09T05:08:48.797Z] 05:08:48 INFO - STDOUT: 1667970528796 Marionette DEBUG Accepted connection 0 from 127.0.0.1:44532
[task 2022-11-09T05:08:48.805Z] 05:08:48 INFO - STDOUT: 1667970528802 geckodriver::marionette DEBUG Connection to Marionette established on 127.0.0.1:37566.
[task 2022-11-09T05:08:48.908Z] 05:08:48 INFO - STDOUT: 1667970528906 Marionette DEBUG 0 -> [0,1,"WebDriver:NewSession",{"webSocketUrl":true}]
[task 2022-11-09T05:08:48.914Z] 05:08:48 INFO - STDOUT: 1667970528912 Marionette DEBUG Waiting for initial application window
[task 2022-11-09T05:08:49.354Z] 05:08:49 INFO - STDOUT: [Child 25133, Main Thread] WARNING: could not set real-time limit in CubebUtils::InitLibrary: file /builds/worker/checkouts/gecko/dom/media/CubebUtils.cpp:714
[task 2022-11-09T05:08:49.408Z] 05:08:49 INFO - STDOUT: [2022-11-09T05:08:49Z WARN webrender::device::gl] Cropping texture upload Box2D((0, 0), (0, 1)) to None
[task 2022-11-09T05:08:49.410Z] 05:08:49 INFO - STDOUT: [2022-11-09T05:08:49Z WARN webrender::device::gl] Cropping texture upload Box2D((0, 0), (0, 1)) to None
[task 2022-11-09T05:08:49.411Z] 05:08:49 INFO - STDOUT: [2022-11-09T05:08:49Z WARN webrender::device::gl] Cropping texture upload Box2D((0, 0), (0, 1)) to None
[task 2022-11-09T05:08:49.444Z] 05:08:49 INFO - STDOUT: [2022-11-09T05:08:49Z WARN webrender::device::gl] Cropping texture upload Box2D((0, 0), (0, 1)) to None
[task 2022-11-09T05:08:49.445Z] 05:08:49 INFO - STDOUT: [2022-11-09T05:08:49Z WARN webrender::device::gl] Cropping texture upload Box2D((0, 0), (0, 1)) to None
[task 2022-11-09T05:08:49.445Z] 05:08:49 INFO - STDOUT: [2022-11-09T05:08:49Z WARN webrender::device::gl] Cropping texture upload Box2D((0, 0), (0, 1)) to None
[task 2022-11-09T05:08:49.459Z] 05:08:49 INFO - STDOUT: [Parent 25048, Main Thread] WARNING: NS_ENSURE_TRUE(mPresShell) failed: file /builds/worker/checkouts/gecko/layout/generic/nsFrameSelection.cpp:1606
[task 2022-11-09T05:08:50.380Z] 05:08:50 INFO - STDOUT: [Child 25158, Main Thread] WARNING: could not set real-time limit in CubebUtils::InitLibrary: file /builds/worker/checkouts/gecko/dom/media/CubebUtils.cpp:714
[task 2022-11-09T05:08:50.419Z] 05:08:50 INFO - STDOUT: [Child 25163, Main Thread] WARNING: could not set real-time limit in CubebUtils::InitLibrary: file /builds/worker/checkouts/gecko/dom/media/CubebUtils.cpp:714
[task 2022-11-09T05:08:50.444Z] 05:08:50 INFO - STDOUT: [Child 25170, Main Thread] WARNING: could not set real-time limit in CubebUtils::InitLibrary: file /builds/worker/checkouts/gecko/dom/media/CubebUtils.cpp:714
[task 2022-11-09T05:08:50.810Z] 05:08:50 INFO - STDOUT: [Parent 25048, Main Thread] WARNING: NS_ENSURE_TRUE(mPresShell) failed: file /builds/worker/checkouts/gecko/layout/generic/nsFrameSelection.cpp:1606
[task 2022-11-09T05:08:50.820Z] 05:08:50 INFO - STDOUT: [Parent 25048, Main Thread] WARNING: NS_ENSURE_TRUE(mPresShell) failed: file /builds/worker/checkouts/gecko/layout/generic/nsFrameSelection.cpp:1606
[task 2022-11-09T05:08:51.211Z] 05:08:51 INFO - STDOUT: [Parent 25048, Main Thread] WARNING: Failed to retarget HTML data delivery to the parser thread.: file /builds/worker/checkouts/gecko/parser/html/nsHtml5StreamParser.cpp:1234
[task 2022-11-09T05:08:51.307Z] 05:08:51 INFO - STDOUT: [Child 25228, Main Thread] WARNING: could not set real-time limit in CubebUtils::InitLibrary: file /builds/worker/checkouts/gecko/dom/media/CubebUtils.cpp:714
[task 2022-11-09T05:08:51.378Z] 05:08:51 INFO - STDOUT: [Child 25228, Main Thread] WARNING: Fallback to FallbackRenderer: file /builds/worker/checkouts/gecko/dom/ipc/BrowserChild.cpp:2823
[task 2022-11-09T05:08:51.387Z] 05:08:51 INFO - STDOUT: [Child 25228, Main Thread] WARNING: Fallback to FallbackRenderer: file /builds/worker/checkouts/gecko/dom/ipc/BrowserChild.cpp:2823
[task 2022-11-09T05:08:51.393Z] 05:08:51 INFO - STDOUT: [Child 25228, Main Thread] WARNING: Fallback to FallbackRenderer: file /builds/worker/checkouts/gecko/dom/ipc/BrowserChild.cpp:2823
[task 2022-11-09T05:08:51.400Z] 05:08:51 INFO - STDOUT: [Child 25228, Main Thread] WARNING: Fallback to FallbackRenderer: file /builds/worker/checkouts/gecko/dom/ipc/BrowserChild.cpp:2823
[task 2022-11-09T05:08:51.408Z] 05:08:51 INFO - STDOUT: [Child 25228, Main Thread] WARNING: Fallback to FallbackRenderer: file /builds/worker/checkouts/gecko/dom/ipc/BrowserChild.cpp:2823
[task 2022-11-09T05:08:51.690Z] 05:08:51 INFO - STDOUT: [2022-11-09T05:08:51Z WARN glean_core::upload] Attempted to enqueue a duplicate ping 0fe64fc7-f7a3-4060-8223-77290d962378 at /submit/firefox-desktop/events/1/0fe64fc7-f7a3-4060-8223-77290d962378.
[task 2022-11-09T05:08:51.696Z] 05:08:51 INFO - STDOUT: [2022-11-09T05:08:51Z WARN glean_core::error_recording] fog.initialization: Timespan value already recorded. New value discarded.
[task 2022-11-09T05:08:52.184Z] 05:08:52 INFO - STDOUT: [Child 25268, Main Thread] WARNING: could not set real-time limit in CubebUtils::InitLibrary: file /builds/worker/checkouts/gecko/dom/media/CubebUtils.cpp:714
[task 2022-11-09T05:08:52.230Z] 05:08:52 INFO - STDOUT: 1667970532228 Marionette TRACE Received observer notification browser-idle-startup-tasks-finished
[task 2022-11-09T05:08:52.231Z] 05:08:52 INFO - STDOUT: 1667970532229 RemoteAgent TRACE Received observer notification browser-idle-startup-tasks-finished
[task 2022-11-09T05:08:52.249Z] 05:08:52 INFO - STDOUT: 1667970532247 RemoteAgent TRACE [3] ProgressListener Start: expectNavigation=false resolveWhenStarted=false unloadTimeout=1600 waitForExplicitStart=false
[task 2022-11-09T05:08:52.249Z] 05:08:52 INFO - STDOUT: 1667970532248 RemoteAgent TRACE [3] ProgressListener Setting unload timer (1600ms)
[task 2022-11-09T05:08:52.250Z] 05:08:52 INFO - STDOUT: 1667970532249 RemoteAgent TRACE [3] Document already finished loading: about:blank
[task 2022-11-09T05:08:52.251Z] 05:08:52 INFO - STDOUT: 1667970532249 RemoteAgent TRACE [3] ProgressListener Stop: has error=false
[task 2022-11-09T05:08:52.254Z] 05:08:52 INFO - STDOUT: DevTools listening on ws://127.0.0.1:9222/devtools/browser/a507b66d-2829-46ad-81fd-fbccdd99ef5d
[task 2022-11-09T05:08:52.267Z] 05:08:52 INFO - STDOUT: 1667970532265 Marionette DEBUG 0 <- [1,1,null,{"sessionId":"ba6c1f76-55ad-410b-ab2d-0bf76cdf289e","capabilities":{"browserName":"firefox","browserVersion":"108.0a1","platformName":"linux","acceptInsecureCerts":false,"pageLoadStrategy":"normal","setWindowRect":true,"timeouts":{"implicit":0,"pageLoad":300000,"script":30000},"strictFileInteractability":false,"unhandledPromptBehavior":"dismiss and notify","moz:accessibilityChecks":false,"moz:buildID":"20221109040422","moz:debuggerAddress":"127.0.0.1:9222","moz:headless":false,"moz:platformVersion":"4.4.0-1014-aws","moz:processID":25048,"moz:profile":"/tmp/tmpx1ngnk8k.mozrunner","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true,"moz:windowless":false,"proxy":{}}}]
[task 2022-11-09T05:08:52.281Z] 05:08:52 INFO - STDOUT: 1667970532277 webdriver::server DEBUG <- 200 OK {"value":{"sessionId":"ba6c1f76-55ad-410b-ab2d-0bf76cdf289e","capabilities":{"acceptInsecureCerts":false,"browserNa ... ctability":false,"timeouts":{"implicit":0,"pageLoad":300000,"script":30000},"unhandledPromptBehavior":"dismiss and notify"}}}
[task 2022-11-09T05:08:52.283Z] 05:08:52 INFO - STDOUT: 1667970532279 webdriver::server DEBUG -> GET /session/ba6c1f76-55ad-410b-ab2d-0bf76cdf289e/window/handles
[task 2022-11-09T05:08:52.283Z] 05:08:52 INFO - STDOUT: 1667970532281 Marionette DEBUG 0 -> [0,2,"WebDriver:GetWindowHandles",{}]
[task 2022-11-09T05:08:52.290Z] 05:08:52 INFO - STDOUT: 1667970532285 Marionette DEBUG 0 <- [1,2,null,["a27aec08-0835-476e-9cde-131c0582e439"]]
[task 2022-11-09T05:08:52.294Z] 05:08:52 INFO - STDOUT: 1667970532289 webdriver::server DEBUG <- 200 OK {"value":["a27aec08-0835-476e-9cde-131c0582e439"]}
[task 2022-11-09T05:08:52.295Z] 05:08:52 INFO - STDOUT: 1667970532291 webdriver::server DEBUG -> DELETE /session/ba6c1f76-55ad-410b-ab2d-0bf76cdf289e
[task 2022-11-09T05:08:52.298Z] 05:08:52 INFO - STDOUT: 1667970532296 Marionette DEBUG 0 -> [0,3,"Marionette:Quit",{"flags":["eForceQuit"]}]
[task 2022-11-09T05:08:52.299Z] 05:08:52 INFO - STDOUT: 1667970532297 Marionette INFO Stopped listening on port 37566
[task 2022-11-09T05:08:52.339Z] 05:08:52 INFO - STDOUT: [Child 25228, Main Thread] WARNING: '!CanSend() || !mManager || !mManager->CanSend()', file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:44
[task 2022-11-09T05:08:52.343Z] 05:08:52 INFO - STDOUT: [Child 25228, Main Thread] WARNING: '!CanSend() || !mManager || !mManager->CanSend()', file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:44
[task 2022-11-09T05:08:52.345Z] 05:08:52 INFO - STDOUT: [Child 25228, Main Thread] WARNING: '!CanSend() || !mManager || !mManager->CanSend()', file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:44
[task 2022-11-09T05:08:52.346Z] 05:08:52 INFO - STDOUT: [Child 25228, Main Thread] WARNING: '!CanSend() || !mManager || !mManager->CanSend()', file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:44
[task 2022-11-09T05:08:52.350Z] 05:08:52 INFO - STDOUT: [Child 25228, Main Thread] WARNING: '!CanSend() || !mManager || !mManager->CanSend()', file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:44
[task 2022-11-09T05:08:52.353Z] 05:08:52 INFO - STDOUT: [Child 25228, Main Thread] WARNING: '!CanSend() || !mManager || !mManager->CanSend()', file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:44
[task 2022-11-09T05:08:52.362Z] 05:08:52 INFO - STDOUT: [Child 25228, Main Thread] WARNING: '!CanSend() || !mManager || !mManager->CanSend()', file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:44
[task 2022-11-09T05:08:52.420Z] 05:08:52 INFO - STDOUT: 1667970532418 Marionette TRACE Received observer notification quit-application
[task 2022-11-09T05:08:52.427Z] 05:08:52 INFO - STDOUT: 1667970532424 Marionette TRACE Received observer notification quit-application
[task 2022-11-09T05:08:52.428Z] 05:08:52 INFO - STDOUT: 1667970532425 Marionette DEBUG Marionette stopped listening
[task 2022-11-09T05:08:52.429Z] 05:08:52 INFO - STDOUT: 1667970532425 RemoteAgent TRACE Received observer notification quit-application
[task 2022-11-09T05:08:52.430Z] 05:08:52 INFO - STDOUT: 1667970532428 Marionette DEBUG 0 <- [1,3,null,{"cause":"shutdown","forced":false,"in_app":true}]
[task 2022-11-09T05:08:52.449Z] 05:08:52 INFO - STDOUT: [Parent 25048, Main Thread] WARNING: '!CanHandleWith(aPresContext)', file /builds/worker/checkouts/gecko/dom/events/IMEStateManager.cpp:500
[task 2022-11-09T05:08:52.467Z] 05:08:52 INFO - STDOUT: [Child 25158, Main Thread] WARNING: '!CanHandleWith(aPresContext)', file /builds/worker/checkouts/gecko/dom/events/IMEStateManager.cpp:500
[task 2022-11-09T05:08:52.483Z] 05:08:52 INFO - STDOUT: [Parent 25048, Compositor] WARNING: Possibly dropping task posted to updater thread: file /builds/worker/checkouts/gecko/gfx/layers/apz/src/APZUpdater.cpp:371
[task 2022-11-09T05:08:52.489Z] 05:08:52 INFO - STDOUT: 1667970532487 RemoteAgent DEBUG Resetting recommended pref browser.contentblocking.features.standard
[task 2022-11-09T05:08:52.490Z] 05:08:52 INFO - STDOUT: 1667970532487 RemoteAgent DEBUG Resetting recommended pref network.cookie.cookieBehavior
[task 2022-11-09T05:08:52.491Z] 05:08:52 INFO - STDOUT: 1667970532488 webdriver::server DEBUG Teardown session
[task 2022-11-09T05:08:52.498Z] 05:08:52 INFO - STDOUT: 1667970532495 Marionette DEBUG Closed connection 0
[task 2022-11-09T05:08:52.543Z] 05:08:52 INFO - STDOUT: [Child 25158, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp:3387
[task 2022-11-09T05:08:52.545Z] 05:08:52 INFO - STDOUT: [Child 25158, Main Thread] WARNING: NS_ENSURE_TRUE(InitStaticMembers()) failed: file /builds/worker/workspace/obj-build/dist/include/mozilla/Preferences.h:129
[task 2022-11-09T05:08:52.552Z] 05:08:52 INFO - STDOUT: [Child 25158, Main Thread] WARNING: NS_ENSURE_TRUE(Preferences::InitStaticMembers()) failed: file /builds/worker/checkouts/gecko/modules/libpref/Preferences.cpp:4628
[task 2022-11-09T05:08:52.634Z] 05:08:52 INFO - STDOUT: [Child 25228, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp:3387
[task 2022-11-09T05:08:52.636Z] 05:08:52 INFO - STDOUT: [Child 25228, Main Thread] WARNING: NS_ENSURE_TRUE(InitStaticMembers()) failed: file /builds/worker/workspace/obj-build/dist/include/mozilla/Preferences.h:129
[task 2022-11-09T05:08:52.644Z] 05:08:52 INFO - STDOUT: [2022-11-09T05:08:52Z WARN xulstore::persist] tried to remove key that isn't in the store
[task 2022-11-09T05:08:52.644Z] 05:08:52 INFO - STDOUT: [2022-11-09T05:08:52Z WARN xulstore::persist] tried to remove key that isn't in the store
[task 2022-11-09T05:08:52.645Z] 05:08:52 INFO - STDOUT: [Child 25228, Main Thread] WARNING: NS_ENSURE_TRUE(Preferences::InitStaticMembers()) failed: file /builds/worker/checkouts/gecko/modules/libpref/Preferences.cpp:4628
[task 2022-11-09T05:08:52.815Z] 05:08:52 INFO - STDOUT: [Parent 25048, Compositor] WARNING: IPC Connection Error: [Parent][PCompositorManagerParent] RunMessage(msgname=PCompositorBridge::Msg___delete__) Channel closing: too late to send/recv, messages will be lost: file /builds/worker/checkouts/gecko/ipc/glue/MessageChannel.cpp:1883
[task 2022-11-09T05:08:52.816Z] 05:08:52 INFO - STDOUT: [Parent 25048, Compositor] WARNING: IPC Connection Error: [Parent][PImageBridgeParent] RunMessage(msgname=PImageBridge::Msg_WillClose) Channel closing: too late to send/recv, messages will be lost: file /builds/worker/checkouts/gecko/ipc/glue/MessageChannel.cpp:1883
[task 2022-11-09T05:08:52.837Z] 05:08:52 INFO - STDOUT: [Parent 25048, IPDL Background] WARNING: quota manager shutdown step: '0.000003s: startCrashBrowserTimer', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3297
[task 2022-11-09T05:08:52.837Z] 05:08:52 INFO - STDOUT: [Parent 25048, IPDL Background] WARNING: quota manager shutdown step: '0.000035s: initiateShutdownWorkThreads', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3297
[task 2022-11-09T05:08:52.837Z] 05:08:52 INFO - STDOUT: [Parent 25048, IPDL Background] WARNING: idb: '0.000043s: starting', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3297
[task 2022-11-09T05:08:52.838Z] 05:08:52 INFO - STDOUT: [Parent 25048, IPDL Background] WARNING: cache: '0.000054s: starting', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3297
[task 2022-11-09T05:08:52.839Z] 05:08:52 INFO - STDOUT: [Parent 25048, IPDL Background] WARNING: sdb: '0.000470s: starting', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3297
[task 2022-11-09T05:08:52.841Z] 05:08:52 INFO - STDOUT: [Parent 25048, IPDL Background] WARNING: fs: '0.000480s: starting', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3297
[task 2022-11-09T05:08:52.842Z] 05:08:52 INFO - STDOUT: [Parent 25048, IPDL Background] WARNING: ls: '0.000486s: starting', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3297
[task 2022-11-09T05:08:52.842Z] 05:08:52 INFO - STDOUT: [Parent 25048, IPDL Background] WARNING: quota manager shutdown step: '0.000496s: startKillActorsTimer', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3297
[task 2022-11-09T05:08:52.843Z] 05:08:52 INFO - STDOUT: [Parent 25048, IPDL Background] WARNING: idb: '0.000557s: Live database entry removed', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3297
[task 2022-11-09T05:08:52.844Z] 05:08:52 INFO - STDOUT: [Parent 25048, IPDL Background] WARNING: idb: '0.000568s: gLiveDatabaseHashtable entry removed', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3297
[task 2022-11-09T05:08:52.845Z] 05:08:52 INFO - STDOUT: [Parent 25048, IPDL Background] WARNING: idb: '0.000680s: Live database entry removed', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3297
[task 2022-11-09T05:08:52.846Z] 05:08:52 INFO - STDOUT: [Parent 25048, IPDL Background] WARNING: idb: '0.000693s: gLiveDatabaseHashtable entry removed', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3297
[task 2022-11-09T05:08:52.847Z] 05:08:52 INFO - STDOUT: [Parent 25048, IPDL Background] WARNING: idb: '0.000762s: Live database entry removed', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3297
[task 2022-11-09T05:08:52.848Z] 05:08:52 INFO - STDOUT: [Parent 25048, IPDL Background] WARNING: idb: '0.000769s: gLiveDatabaseHashtable entry removed', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3297
[task 2022-11-09T05:08:52.848Z] 05:08:52 INFO - STDOUT: [Parent 25048, IPDL Background] WARNING: idb: '0.002386s: Live database entry removed', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3297
[task 2022-11-09T05:08:52.850Z] 05:08:52 INFO - STDOUT: [Parent 25048, IPDL Background] WARNING: idb: '0.002463s: Live database entry removed', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3297
[task 2022-11-09T05:08:52.850Z] 05:08:52 INFO - STDOUT: [Parent 25048, IPDL Background] WARNING: idb: '0.002471s: gLiveDatabaseHashtable entry removed', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3297
[task 2022-11-09T05:08:52.851Z] 05:08:52 INFO - STDOUT: [Parent 25048, IPDL Background] WARNING: quota manager shutdown step: '0.003202s: stopKillActorsTimer', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3297
[task 2022-11-09T05:08:52.852Z] 05:08:52 INFO - STDOUT: [Parent 25048, IPDL Background] WARNING: quota manager shutdown step: '0.003223s: shutdownAndJoinWorkThreads', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3297
[task 2022-11-09T05:08:52.853Z] 05:08:52 INFO - STDOUT: [Parent 25048, IPDL Background] WARNING: idb: '0.003230s: completed', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3297
[task 2022-11-09T05:08:52.854Z] 05:08:52 INFO - STDOUT: [Parent 25048, IPDL Background] WARNING: cache: '0.003265s: completed', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3297
[task 2022-11-09T05:08:52.855Z] 05:08:52 INFO - STDOUT: [Parent 25048, IPDL Background] WARNING: sdb: '0.003272s: completed', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3297
[task 2022-11-09T05:08:52.868Z] 05:08:52 INFO - STDOUT: [Parent 25048, IPDL Background] WARNING: fs: '0.003277s: completed', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3297
[task 2022-11-09T05:08:52.869Z] 05:08:52 INFO - STDOUT: [Parent 25048, IPDL Background] WARNING: ls: '0.003283s: completed', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3297
[task 2022-11-09T05:08:52.870Z] 05:08:52 INFO - STDOUT: [Parent 25048, IPDL Background] WARNING: quota manager shutdown step: '0.003289s: shutdownAndJoinIOThread', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3297
[task 2022-11-09T05:08:52.872Z] 05:08:52 INFO - STDOUT: [Parent 25048, IPDL Background] WARNING: quota manager shutdown step: '0.004934s: invalidatePendingDirectoryLocks', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3297
[task 2022-11-09T05:08:52.874Z] 05:08:52 INFO - STDOUT: [Parent 25048, IPDL Background] WARNING: quota manager shutdown step: '0.004953s: stopCrashBrowserTimer', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3297
[task 2022-11-09T05:08:52.876Z] 05:08:52 INFO - STDOUT: [Child 25170, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp:3387
[task 2022-11-09T05:08:52.876Z] 05:08:52 INFO - STDOUT: [Child 25170, Main Thread] WARNING: NS_ENSURE_TRUE(InitStaticMembers()) failed: file /builds/worker/workspace/obj-build/dist/include/mozilla/Preferences.h:129
[task 2022-11-09T05:08:52.877Z] 05:08:52 INFO - STDOUT: [Child 25163, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp:3387
[task 2022-11-09T05:08:52.878Z] 05:08:52 INFO - STDOUT: [Child 25170, Main Thread] WARNING: NS_ENSURE_TRUE(Preferences::InitStaticMembers()) failed: file /builds/worker/checkouts/gecko/modules/libpref/Preferences.cpp:4628
[task 2022-11-09T05:08:52.879Z] 05:08:52 INFO - STDOUT: [Child 25133, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp:3387
[task 2022-11-09T05:08:52.880Z] 05:08:52 INFO - STDOUT: [Child 25133, Main Thread] WARNING: NS_ENSURE_TRUE(InitStaticMembers()) failed: file /builds/worker/workspace/obj-build/dist/include/mozilla/Preferences.h:129
[task 2022-11-09T05:08:52.881Z] 05:08:52 INFO - STDOUT: [Child 25268, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp:3387
[task 2022-11-09T05:08:52.882Z] 05:08:52 INFO - STDOUT: [Child 25268, Main Thread] WARNING: NS_ENSURE_TRUE(InitStaticMembers()) failed: file /builds/worker/workspace/obj-build/dist/include/mozilla/Preferences.h:129
[task 2022-11-09T05:08:52.882Z] 05:08:52 INFO - STDOUT: [Child 25163, Main Thread] WARNING: NS_ENSURE_TRUE(InitStaticMembers()) failed: file /builds/worker/workspace/obj-build/dist/include/mozilla/Preferences.h:129
[task 2022-11-09T05:08:52.883Z] 05:08:52 INFO - STDOUT: [Child 25133, Main Thread] WARNING: NS_ENSURE_TRUE(Preferences::InitStaticMembers()) failed: file /builds/worker/checkouts/gecko/modules/libpref/Preferences.cpp:4628
[task 2022-11-09T05:08:52.884Z] 05:08:52 INFO - STDOUT: [Child 25268, Main Thread] WARNING: NS_ENSURE_TRUE(Preferences::InitStaticMembers()) failed: file /builds/worker/checkouts/gecko/modules/libpref/Preferences.cpp:4628
[task 2022-11-09T05:08:52.887Z] 05:08:52 INFO - STDOUT: [Child 25163, Main Thread] WARNING: NS_ENSURE_TRUE(Preferences::InitStaticMembers()) failed: file /builds/worker/checkouts/gecko/modules/libpref/Preferences.cpp:4628
[task 2022-11-09T05:08:52.928Z] 05:08:52 INFO - STDOUT: WARNING: A blocker encountered an error while we were waiting.
[task 2022-11-09T05:08:52.928Z] 05:08:52 INFO - STDOUT: Blocker: Waiting for ping task
[task 2022-11-09T05:08:52.931Z] 05:08:52 INFO - STDOUT: Phase: TelemetryController: Waiting for pending ping activity
[task 2022-11-09T05:08:52.932Z] 05:08:52 INFO - STDOUT: State: (none)
[task 2022-11-09T05:08:52.933Z] 05:08:52 INFO - STDOUT: 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 2022-11-09T05:08:52.933Z] 05:08:52 INFO - STDOUT: WARNING: addBlocker@resource://gre/modules/AsyncShutdown.jsm:703:15
[task 2022-11-09T05:08:52.934Z] 05:08:52 INFO - STDOUT: addBlocker@resource://gre/modules/AsyncShutdown.jsm:511:26
[task 2022-11-09T05:08:52.935Z] 05:08:52 INFO - STDOUT: addBlocker@resource://gre/modules/AsyncShutdown.jsm:450:15
[task 2022-11-09T05:08:52.935Z] 05:08:52 INFO - STDOUT: setupShutdown@resource://gre/modules/osfile/osfile_async_front.jsm:1563:28
[task 2022-11-09T05:08:52.936Z] 05:08:52 INFO - STDOUT: @resource://gre/modules/osfile/osfile_async_front.jsm:1583:16
[task 2022-11-09T05:08:52.937Z] 05:08:52 INFO - STDOUT: @resource://gre/modules/osfile.jsm:12:30
[task 2022-11-09T05:08:52.937Z] 05:08:52 INFO - STDOUT: @resource://gre/modules/TelemetryStorage.jsm:19:28
[task 2022-11-09T05:08:52.938Z] 05:08:52 INFO - STDOUT: promiseArchivePing@resource://gre/modules/TelemetryArchive.jsm:103:5
[task 2022-11-09T05:08:52.939Z] 05:08:52 INFO - STDOUT: promiseArchivePing@resource://gre/modules/TelemetryArchive.jsm:63:33
[task 2022-11-09T05:08:52.939Z] 05:08:52 INFO - STDOUT: _submitPingLogic@resource://gre/modules/TelemetryControllerParent.jsm:554:48
[task 2022-11-09T05:08:52.940Z] 05:08:52 INFO - STDOUT: send@resource://gre/modules/TelemetryControllerParent.jsm:642:24
[task 2022-11-09T05:08:52.941Z] 05:08:52 INFO - STDOUT: submitExternalPing@resource://gre/modules/TelemetryControllerParent.jsm:182:17
[task 2022-11-09T05:08:52.942Z] 05:08:52 INFO - STDOUT: sendPing@resource://gre/modules/EventPing.jsm:51:30
[task 2022-11-09T05:08:52.943Z] 05:08:52 INFO - STDOUT: _submitPing@resource://gre/modules/EventPing.jsm:229:12
[task 2022-11-09T05:08:52.943Z] 05:08:52 INFO - STDOUT: shutdown@resource://gre/modules/EventPing.jsm:112:10
[task 2022-11-09T05:08:52.944Z] 05:08:52 INFO - STDOUT: _cleanupOnShutdown@resource://gre/modules/TelemetryControllerParent.jsm:954:31
[task 2022-11-09T05:08:52.945Z] 05:08:52 INFO - STDOUT: shutdown/<@resource://gre/modules/TelemetryControllerParent.jsm:1024:24
[task 2022-11-09T05:08:52.946Z] 05:08:52 INFO - STDOUT: observe@resource://gre/modules/AsyncShutdown.jsm:560:16
[task 2022-11-09T05:08:52.973Z] 05:08:52 INFO - STDOUT: WARNING: A blocker encountered an error while we were waiting.
[task 2022-11-09T05:08:52.973Z] 05:08:52 INFO - STDOUT: Blocker: Waiting for ping task
[task 2022-11-09T05:08:52.973Z] 05:08:52 INFO - STDOUT: Phase: TelemetryController: Waiting for pending ping activity
[task 2022-11-09T05:08:52.974Z] 05:08:52 INFO - STDOUT: State: (none)
[task 2022-11-09T05:08:52.975Z] 05:08:52 INFO - STDOUT: 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 2022-11-09T05:08:52.976Z] 05:08:52 INFO - STDOUT: WARNING: addBlocker@resource://gre/modules/AsyncShutdown.jsm:703:15
[task 2022-11-09T05:08:52.977Z] 05:08:52 INFO - STDOUT: addBlocker@resource://gre/modules/AsyncShutdown.jsm:511:26
[task 2022-11-09T05:08:52.978Z] 05:08:52 INFO - STDOUT: addBlocker@resource://gre/modules/AsyncShutdown.jsm:450:15
[task 2022-11-09T05:08:52.979Z] 05:08:52 INFO - STDOUT: setupShutdown@resource://gre/modules/osfile/osfile_async_front.jsm:1563:28
[task 2022-11-09T05:08:52.979Z] 05:08:52 INFO - STDOUT: @resource://gre/modules/osfile/osfile_async_front.jsm:1583:16
[task 2022-11-09T05:08:52.980Z] 05:08:52 INFO - STDOUT: @resource://gre/modules/osfile.jsm:12:30
[task 2022-11-09T05:08:52.981Z] 05:08:52 INFO - STDOUT: @resource://gre/modules/TelemetryStorage.jsm:19:28
[task 2022-11-09T05:08:52.982Z] 05:08:52 INFO - STDOUT: promiseArchivePing@resource://gre/modules/TelemetryArchive.jsm:103:5
[task 2022-11-09T05:08:52.983Z] 05:08:52 INFO - STDOUT: promiseArchivePing@resource://gre/modules/TelemetryArchive.jsm:63:33
[task 2022-11-09T05:08:52.984Z] 05:08:52 INFO - STDOUT: _submitPingLogic@resource://gre/modules/TelemetryControllerParent.jsm:554:48
[task 2022-11-09T05:08:52.984Z] 05:08:52 INFO - STDOUT: send@resource://gre/modules/TelemetryControllerParent.jsm:642:24
[task 2022-11-09T05:08:52.985Z] 05:08:52 INFO - STDOUT: submitExternalPing@resource://gre/modules/TelemetryControllerParent.jsm:182:17
[task 2022-11-09T05:08:52.986Z] 05:08:52 INFO - STDOUT: saveShutdownPings@resource://gre/modules/TelemetrySession.jsm:982:34
[task 2022-11-09T05:08:52.987Z] 05:08:52 INFO - STDOUT: shutdownChromeProcess/cleanup/<@resource://gre/modules/TelemetrySession.jsm:1232:20
[task 2022-11-09T05:08:52.988Z] 05:08:52 INFO - STDOUT: cleanup@resource://gre/modules/TelemetrySession.jsm:1239:9
[task 2022-11-09T05:08:52.989Z] 05:08:52 INFO - STDOUT: shutdownChromeProcess@resource://gre/modules/TelemetrySession.jsm:1256:14
[task 2022-11-09T05:08:52.989Z] 05:08:52 INFO - STDOUT: shutdown@resource://gre/modules/TelemetrySession.jsm:247:17
[task 2022-11-09T05:08:52.990Z] 05:08:52 INFO - STDOUT: _cleanupOnShutdown@resource://gre/modules/TelemetryControllerParent.jsm:973:35
[task 2022-11-09T05:08:52.991Z] 05:08:52 INFO - STDOUT: observe@resource://gre/modules/AsyncShutdown.jsm:560:16
[task 2022-11-09T05:08:53.002Z] 05:08:53 INFO - STDOUT: WARNING: A blocker encountered an error while we were waiting.
[task 2022-11-09T05:08:53.003Z] 05:08:53 INFO - STDOUT: Blocker: TelemetryController: shutting down
[task 2022-11-09T05:08:53.003Z] 05:08:53 INFO - STDOUT: Phase: profile-before-change-telemetry
[task 2022-11-09T05:08:53.005Z] 05:08:53 INFO - STDOUT: 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.jsm:703:15
[task 2022-11-09T05:08:53.008Z] 05:08:53 INFO - STDOUT: addBlocker@resource://gre/modules/AsyncShutdown.jsm:511:26
[task 2022-11-09T05:08:53.008Z] 05:08:53 INFO - STDOUT: addBlocker@resource://gre/modules/AsyncShutdown.jsm:450:15
[task 2022-11-09T05:08:53.009Z] 05:08:53 INFO - STDOUT: setupShutdown@resource://gre/modules/osfile/osfile_async_front.jsm:1563:28
[task 2022-11-09T05:08:53.009Z] 05:08:53 INFO - STDOUT: @resource://gre/modules/osfile/osfile_async_front.jsm:1583:16
[task 2022-11-09T05:08:53.009Z] 05:08:53 INFO - STDOUT: @resource://gre/modules/osfile.jsm:12:30
[task 2022-11-09T05:08:53.009Z] 05:08:53 INFO - STDOUT: @resource://gre/modules/TelemetryStorage.jsm:19:28
[task 2022-11-09T05:08:53.010Z] 05:08:53 INFO - STDOUT: getShutdownState@resource://gre/modules/TelemetrySend.jsm:1687:7
[task 2022-11-09T05:08:53.013Z] 05:08:53 INFO - STDOUT: getShutdownState@resource://gre/modules/TelemetrySend.jsm:369:30
[task 2022-11-09T05:08:53.013Z] 05:08:53 INFO - STDOUT: _getState@resource://gre/modules/TelemetryControllerParent.jsm:1072:38
[task 2022-11-09T05:08:53.013Z] 05:08:53 INFO - STDOUT: setupTelemetry/<@resource://gre/modules/TelemetryControllerParent.jsm:931:18
[task 2022-11-09T05:08:53.014Z] 05:08:53 INFO - STDOUT: safeGetState@resource://gre/modules/AsyncShutdown.jsm:242:17
[task 2022-11-09T05:08:53.014Z] 05:08:53 INFO - STDOUT: Barrier/addBlocker/promise<@resource://gre/modules/AsyncShutdown.jsm:751:20
[task 2022-11-09T05:08:53.014Z] 05:08:53 INFO - STDOUT: observe@resource://gre/modules/AsyncShutdown.jsm:560:16
[task 2022-11-09T05:08:53.015Z] 05:08:53 INFO - STDOUT: 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 2022-11-09T05:08:53.016Z] 05:08:53 INFO - STDOUT: WARNING: addBlocker@resource://gre/modules/AsyncShutdown.jsm:703:15
[task 2022-11-09T05:08:53.017Z] 05:08:53 INFO - STDOUT: addBlocker@resource://gre/modules/AsyncShutdown.jsm:511:26
[task 2022-11-09T05:08:53.018Z] 05:08:53 INFO - STDOUT: addBlocker@resource://gre/modules/AsyncShutdown.jsm:450:15
[task 2022-11-09T05:08:53.019Z] 05:08:53 INFO - STDOUT: setupShutdown@resource://gre/modules/osfile/osfile_async_front.jsm:1563:28
[task 2022-11-09T05:08:53.019Z] 05:08:53 INFO - STDOUT: @resource://gre/modules/osfile/osfile_async_front.jsm:1583:16
[task 2022-11-09T05:08:53.020Z] 05:08:53 INFO - STDOUT: @resource://gre/modules/osfile.jsm:12:30
[task 2022-11-09T05:08:53.021Z] 05:08:53 INFO - STDOUT: @resource://gre/modules/TelemetryStorage.jsm:19:28
[task 2022-11-09T05:08:53.022Z] 05:08:53 INFO - STDOUT: removeAbortedSessionPing@resource://gre/modules/TelemetryControllerParent.jsm:735:5
[task 2022-11-09T05:08:53.023Z] 05:08:53 INFO - STDOUT: removeAbortedSessionPing@resource://gre/modules/TelemetryControllerParent.jsm:249:17
[task 2022-11-09T05:08:53.024Z] 05:08:53 INFO - STDOUT: shutdownChromeProcess/cleanup/<@resource://gre/modules/TelemetrySession.jsm:1235:42
[task 2022-11-09T05:08:53.025Z] 05:08:53 INFO - STDOUT: observe@resource://gre/modules/AsyncShutdown.jsm:560:16
[task 2022-11-09T05:08:53.026Z] 05:08:53 INFO - STDOUT: JavaScript error: resource://gre/modules/AsyncShutdown.jsm, line 703: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange"
[task 2022-11-09T05:08:53.027Z] 05:08:53 INFO - STDOUT: JavaScript error: resource://gre/modules/AsyncShutdown.jsm, line 703: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange"
[task 2022-11-09T05:08:53.028Z] 05:08:53 INFO - STDOUT: JavaScript error: resource://gre/modules/AsyncShutdown.jsm, line 703: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange"
[task 2022-11-09T05:08:53.029Z] 05:08:53 INFO - STDOUT: JavaScript error: resource://gre/modules/AsyncShutdown.jsm, line 703: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange"
[task 2022-11-09T05:08:53.030Z] 05:08:53 INFO - STDOUT: JavaScript error: resource://gre/modules/AsyncShutdown.jsm, line 703: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange"
[task 2022-11-09T05:08:53.031Z] 05:08:53 INFO - STDOUT: [Parent 25048, Compositor] WARNING: IPC Connection Error: [Parent][PImageBridgeParent] RunMessage(msgname=PImageBridge::Msg_WillClose) Channel closing: too late to send/recv, messages will be lost: file /builds/worker/checkouts/gecko/ipc/glue/MessageChannel.cpp:1883
[task 2022-11-09T05:08:53.691Z] 05:08:53 INFO - STDOUT: [Parent 25048, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp:3387
[task 2022-11-09T05:08:53.703Z] 05:08:53 INFO - STDOUT: [Parent 25048, Main Thread] WARNING: NS_ENSURE_TRUE(InitStaticMembers()) failed: file /builds/worker/workspace/obj-build/dist/include/mozilla/Preferences.h:129
[task 2022-11-09T05:08:53.718Z] 05:08:53 INFO - STDOUT: [Parent 25048, Main Thread] WARNING: NS_ENSURE_TRUE(Preferences::InitStaticMembers()) failed: file /builds/worker/checkouts/gecko/modules/libpref/Preferences.cpp:4628
[task 2022-11-09T05:08:53.791Z] 05:08:53 INFO - STDOUT: 1667970533790 geckodriver::browser DEBUG Browser process stopped: exit status: 0
[task 2022-11-09T05:08:53.793Z] 05:08:53 INFO - STDOUT: 1667970533790 webdriver::server DEBUG <- 200 OK {"value":null}
[task 2022-11-09T05:08:53.815Z] 05:08:53 INFO - STDOUT: Running command: ['/builds/worker/fetches/geckodriver', '--port', '42886', '-vv']
[task 2022-11-09T05:08:53.821Z] 05:08:53 INFO - STDOUT: /builds/worker/fetches/geckodriver: error: Address in use (os error 98)
[task 2022-11-09T05:08:53.822Z] 05:08:53 INFO - STDOUT: geckodriver 0.32.0 (711dfd3885f5 2022-11-04 18:06 +0000)
[task 2022-11-09T05:08:53.824Z] 05:08:53 INFO - STDOUT: WebDriver implementation for Firefox
[task 2022-11-09T05:08:53.825Z] 05:08:53 INFO - STDOUT: USAGE:
[task 2022-11-09T05:08:53.825Z] 05:08:53 INFO - STDOUT: geckodriver [OPTIONS]
[task 2022-11-09T05:08:53.825Z] 05:08:53 INFO - STDOUT: OPTIONS:
[task 2022-11-09T05:08:53.825Z] 05:08:53 INFO - STDOUT: --allow-hosts <ALLOW_HOSTS>...
[task 2022-11-09T05:08:53.826Z] 05:08:53 INFO - STDOUT: List of hostnames to allow. By default the value of --host is allowed, and in addition
[task 2022-11-09T05:08:53.827Z] 05:08:53 INFO - STDOUT: if that's a well known local address, other variations on well known local addresses are
[task 2022-11-09T05:08:53.828Z] 05:08:53 INFO - STDOUT: allowed. If --allow-hosts is provided only exactly those hosts are allowed.
[task 2022-11-09T05:08:53.828Z] 05:08:53 INFO - STDOUT: --allow-origins <ALLOW_ORIGINS>...
[task 2022-11-09T05:08:53.829Z] 05:08:53 INFO - STDOUT: List of request origins to allow. These must be formatted as scheme://host:port. By
[task 2022-11-09T05:08:53.830Z] 05:08:53 INFO - STDOUT: default any request with an origin header is rejected. If --allow-origins is provided
[task 2022-11-09T05:08:53.831Z] 05:08:53 INFO - STDOUT: then only exactly those origins are allowed.
[task 2022-11-09T05:08:53.831Z] 05:08:53 INFO - STDOUT: --android-storage <ANDROID_STORAGE>
[task 2022-11-09T05:08:53.832Z] 05:08:53 INFO - STDOUT: Selects storage location to be used for test data (deprecated). [possible values: auto,
[task 2022-11-09T05:08:53.833Z] 05:08:53 INFO - STDOUT: app, internal, sdcard]
[task 2022-11-09T05:08:53.833Z] 05:08:53 INFO - STDOUT: -b, --binary <BINARY>
[task 2022-11-09T05:08:53.834Z] 05:08:53 INFO - STDOUT: Path to the Firefox binary
[task 2022-11-09T05:08:53.834Z] 05:08:53 INFO - STDOUT: --connect-existing
[task 2022-11-09T05:08:53.835Z] 05:08:53 INFO - STDOUT: Connect to an existing Firefox instance
[task 2022-11-09T05:08:53.836Z] 05:08:53 INFO - STDOUT: -h, --help
[task 2022-11-09T05:08:53.836Z] 05:08:53 INFO - STDOUT: Prints this message
[task 2022-11-09T05:08:53.837Z] 05:08:53 INFO - STDOUT: --host <HOST>
[task 2022-11-09T05:08:53.838Z] 05:08:53 INFO - STDOUT: Host IP to use for WebDriver server [default: 127.0.0.1]
[task 2022-11-09T05:08:53.838Z] 05:08:53 INFO - STDOUT: --jsdebugger
[task 2022-11-09T05:08:53.839Z] 05:08:53 INFO - STDOUT: Attach browser toolbox debugger for Firefox
[task 2022-11-09T05:08:53.840Z] 05:08:53 INFO - STDOUT: --log <LEVEL>
[task 2022-11-09T05:08:53.840Z] 05:08:53 INFO - STDOUT: Set Gecko log level [possible values: fatal, error, warn, info, config, debug, trace]
[task 2022-11-09T05:08:53.841Z] 05:08:53 INFO - STDOUT: --log-no-truncate
[task 2022-11-09T05:08:53.842Z] 05:08:53 INFO - STDOUT: Disable truncation of long log lines
[task 2022-11-09T05:08:53.842Z] 05:08:53 INFO - STDOUT: --marionette-host <HOST>
[task 2022-11-09T05:08:53.843Z] 05:08:53 INFO - STDOUT: Host to use to connect to Gecko [default: 127.0.0.1]
[task 2022-11-09T05:08:53.844Z] 05:08:53 INFO - STDOUT: --marionette-port <PORT>
[task 2022-11-09T05:08:53.844Z] 05:08:53 INFO - STDOUT: Port to use to connect to Gecko [default: system-allocated port]
[task 2022-11-09T05:08:53.845Z] 05:08:53 INFO - STDOUT: -p, --port <PORT>
[task 2022-11-09T05:08:53.846Z] 05:08:53 INFO - STDOUT: Port to use for WebDriver server [default: 4444]
[task 2022-11-09T05:08:53.846Z] 05:08:53 INFO - STDOUT: --profile-root <PROFILE_ROOT>
[task 2022-11-09T05:08:53.847Z] 05:08:53 INFO - STDOUT: Directory in which to create profiles. Defaults to the system temporary directory.
[task 2022-11-09T05:08:53.848Z] 05:08:53 INFO - STDOUT: -v
[task 2022-11-09T05:08:53.849Z] 05:08:53 INFO - STDOUT: Log level verbosity (-v for debug and -vv for trace level)
[task 2022-11-09T05:08:53.849Z] 05:08:53 INFO - STDOUT: -V, --version
[task 2022-11-09T05:08:53.850Z] 05:08:53 INFO - STDOUT: Prints version and copying information
[task 2022-11-09T05:08:53.851Z] 05:08:53 INFO - STDOUT: --websocket-port <PORT>
[task 2022-11-09T05:08:53.851Z] 05:08:53 INFO - STDOUT: Port to use to connect to WebDriver BiDi [default: 9222]
[task 2022-11-09T05:08:53.970Z] 05:08:53 INFO - STDOUT: FAILED
[task 2022-11-09T05:08:53.971Z] 05:08:53 INFO - STDOUT: =================================== FAILURES ===================================
[task 2022-11-09T05:08:53.972Z] 05:08:53 INFO - STDOUT: __________________ test_marionette_fallback_webdriver_session __________________
[task 2022-11-09T05:08:53.974Z] 05:08:53 INFO - STDOUT: configuration = {'capabilities': {'moz:firefoxOptions': {'args': ['--profile', '/tmp/tmpx1ngnk8k.mozrunner'], 'binary': '/builds/worke...}}, 'host': '127.0.0.1', 'port': 42986, 'webdriver': {'args': ['-vv'], 'binary': '/builds/worker/fetches/geckodriver'}}
[task 2022-11-09T05:08:53.975Z] 05:08:53 INFO - STDOUT: geckodriver = <function geckodriver.<locals>._geckodriver at 0x7fd2fe528268>
[task 2022-11-09T05:08:53.976Z] 05:08:53 INFO - STDOUT: def test_marionette_fallback_webdriver_session(configuration, geckodriver):
[task 2022-11-09T05:08:53.976Z] 05:08:53 INFO - STDOUT: config = deepcopy(configuration)
[task 2022-11-09T05:08:53.977Z] 05:08:53 INFO - STDOUT: config["capabilities"]["webSocketUrl"] = True
[task 2022-11-09T05:08:53.978Z] 05:08:53 INFO - STDOUT:
[task 2022-11-09T05:08:53.979Z] 05:08:53 INFO - STDOUT: prefs = config["capabilities"]["moz:firefoxOptions"].get("prefs", {})
[task 2022-11-09T05:08:53.980Z] 05:08:53 INFO - STDOUT: prefs.update({"remote.active-protocols": 2})
[task 2022-11-09T05:08:53.980Z] 05:08:53 INFO - STDOUT: config["capabilities"]["moz:firefoxOptions"]["prefs"] = prefs
[task 2022-11-09T05:08:53.981Z] 05:08:53 INFO - STDOUT:
[task 2022-11-09T05:08:53.982Z] 05:08:53 INFO - STDOUT: try:
[task 2022-11-09T05:08:53.983Z] 05:08:53 INFO - STDOUT: driver = geckodriver(config=config)
[task 2022-11-09T05:08:53.983Z] 05:08:53 INFO - STDOUT: driver.new_session()
[task 2022-11-09T05:08:53.984Z] 05:08:53 INFO - STDOUT:
[task 2022-11-09T05:08:53.985Z] 05:08:53 INFO - STDOUT: assert driver.session.capabilities.get("webSocketUrl") is None
[task 2022-11-09T05:08:53.986Z] 05:08:53 INFO - STDOUT:
[task 2022-11-09T05:08:53.986Z] 05:08:53 INFO - STDOUT: # Sanity check that Marionette works as expected and by default returns
[task 2022-11-09T05:08:53.997Z] 05:08:53 INFO -
[task 2022-11-09T05:08:53.997Z] 05:08:53 INFO - TEST-UNEXPECTED-FAIL | /_mozilla/webdriver/new_session/bidi_disabled.py | test_marionette_fallback_webdriver_session - ConnectionRefusedError: [Errno 111] Connection refused
[task 2022-11-09T05:08:53.997Z] 05:08:53 INFO - configuration = {'capabilities': {'moz:firefoxOptions': {'args': ['--profile', '/tmp/tmpx1ngnk8k.mozrunner'], 'binary': '/builds/worke...}}, 'host': '127.0.0.1', 'port': 42986, 'webdriver': {'args': ['-vv'], 'binary': '/builds/worker/fetches/geckodriver'}}
[task 2022-11-09T05:08:53.997Z] 05:08:53 INFO - geckodriver = <function geckodriver.<locals>._geckodriver at 0x7fd2fe528268>
[task 2022-11-09T05:08:53.997Z] 05:08:53 INFO -
[task 2022-11-09T05:08:53.997Z] 05:08:53 INFO - def test_marionette_fallback_webdriver_session(configuration, geckodriver):
[task 2022-11-09T05:08:53.998Z] 05:08:53 INFO - config = deepcopy(configuration)
[task 2022-11-09T05:08:53.998Z] 05:08:53 INFO - config["capabilities"]["webSocketUrl"] = True
[task 2022-11-09T05:08:53.998Z] 05:08:53 INFO -
[task 2022-11-09T05:08:53.999Z] 05:08:53 INFO - prefs = config["capabilities"]["moz:firefoxOptions"].get("prefs", {})
[task 2022-11-09T05:08:53.999Z] 05:08:53 INFO - prefs.update({"remote.active-protocols": 2})
[task 2022-11-09T05:08:53.999Z] 05:08:53 INFO - config["capabilities"]["moz:firefoxOptions"]["prefs"] = prefs
[task 2022-11-09T05:08:53.999Z] 05:08:53 INFO -
[task 2022-11-09T05:08:53.999Z] 05:08:53 INFO - try:
[task 2022-11-09T05:08:54.000Z] 05:08:54 INFO - driver = geckodriver(config=config)
[task 2022-11-09T05:08:54.000Z] 05:08:54 INFO - driver.new_session()
[task 2022-11-09T05:08:54.000Z] 05:08:54 INFO -
[task 2022-11-09T05:08:54.001Z] 05:08:54 INFO - assert driver.session.capabilities.get("webSocketUrl") is None
[task 2022-11-09T05:08:54.001Z] 05:08:54 INFO -
[task 2022-11-09T05:08:54.001Z] 05:08:54 INFO - # Sanity check that Marionette works as expected and by default returns
[task 2022-11-09T05:08:54.001Z] 05:08:54 INFO - # at least one window handle
[task 2022-11-09T05:08:54.002Z] 05:08:54 INFO - assert len(driver.session.handles) >= 1
[task 2022-11-09T05:08:54.002Z] 05:08:54 INFO -
[task 2022-11-09T05:08:54.002Z] 05:08:54 INFO - finally:
[task 2022-11-09T05:08:54.002Z] 05:08:54 INFO - driver.stop()
[task 2022-11-09T05:08:54.002Z] 05:08:54 INFO -
[task 2022-11-09T05:08:54.002Z] 05:08:54 INFO - # WebDriver BiDi has to be re-enabled. Because we cannot easily
[task 2022-11-09T05:08:54.002Z] 05:08:54 INFO - # get rid of the value let geckodriver overwrite it with the current
[task 2022-11-09T05:08:54.003Z] 05:08:54 INFO - # default.
[task 2022-11-09T05:08:54.003Z] 05:08:54 INFO - prefs.update({"remote.active-protocols": 3})
[task 2022-11-09T05:08:54.003Z] 05:08:54 INFO -
[task 2022-11-09T05:08:54.003Z] 05:08:54 INFO - driver = geckodriver(config=config)
[task 2022-11-09T05:08:54.003Z] 05:08:54 INFO - > driver.new_session()
[task 2022-11-09T05:08:54.003Z] 05:08:54 INFO -
[task 2022-11-09T05:08:54.004Z] 05:08:54 INFO - config = {'capabilities': {'moz:firefoxOptions': {'args': ['--profile',
[task 2022-11-09T05:08:54.004Z] 05:08:54 INFO - '/tmp/tmpx1ngnk8k.mozrunner'],
[task 2022-11-09T05:08:54.004Z] 05:08:54 INFO - 'binary': '/builds/worker/workspace/build/application/firefox/firefox',
[task 2022-11-09T05:08:54.004Z] 05:08:54 INFO - 'prefs': {'remote.active-protocols': 3}},
[task 2022-11-09T05:08:54.004Z] 05:08:54 INFO - 'webSocketUrl': True},
[task 2022-11-09T05:08:54.004Z] 05:08:54 INFO - 'host': '127.0.0.1',
[task 2022-11-09T05:08:54.004Z] 05:08:54 INFO - 'port': 42986,
[task 2022-11-09T05:08:54.004Z] 05:08:54 INFO - 'webdriver': {'args': ['-vv'], 'binary': '/builds/worker/fetches/geckodriver'}}
[task 2022-11-09T05:08:54.004Z] 05:08:54 INFO - configuration = {'capabilities': {'moz:firefoxOptions': {'args': ['--profile',
[task 2022-11-09T05:08:54.004Z] 05:08:54 INFO - '/tmp/tmpx1ngnk8k.mozrunner'],
[task 2022-11-09T05:08:54.005Z] 05:08:54 INFO - 'binary': '/builds/worker/workspace/build/application/firefox/firefox'}},
[task 2022-11-09T05:08:54.005Z] 05:08:54 INFO - 'host': '127.0.0.1',
[task 2022-11-09T05:08:54.005Z] 05:08:54 INFO - 'port': 42986,
[task 2022-11-09T05:08:54.005Z] 05:08:54 INFO - 'webdriver': {'args': ['-vv'], 'binary': '/builds/worker/fetches/geckodriver'}}
[task 2022-11-09T05:08:54.005Z] 05:08:54 INFO - driver = <support.fixtures.Geckodriver object at 0x7fd30d9e1470>
[task 2022-11-09T05:08:54.006Z] 05:08:54 INFO - geckodriver = <function geckodriver.<locals>._geckodriver at 0x7fd2fe528268>
[task 2022-11-09T05:08:54.006Z] 05:08:54 INFO - prefs = {'remote.active-protocols': 3}
[task 2022-11-09T05:08:54.006Z] 05:08:54 INFO -
[task 2022-11-09T05:08:54.006Z] 05:08:54 INFO - tests/web-platform/mozilla/tests/webdriver/new_session/bidi_disabled.py:31:
[task 2022-11-09T05:08:54.006Z] 05:08:54 INFO - _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
[task 2022-11-09T05:08:54.006Z] 05:08:54 INFO - tests/web-platform/mozilla/tests/webdriver/support/fixtures.py:252: in new_session
[task 2022-11-09T05:08:54.006Z] 05:08:54 INFO - self.session.start()
[task 2022-11-09T05:08:54.006Z] 05:08:54 INFO - self = <support.fixtures.Geckodriver object at 0x7fd30d9e1470>
[task 2022-11-09T05:08:54.007Z] 05:08:54 INFO - tests/web-platform/tests/tools/webdriver/webdriver/client.py:561: in start
[task 2022-11-09T05:08:54.007Z] 05:08:54 INFO - value = self.send_command("POST", "session", body=body)
[task 2022-11-09T05:08:54.007Z] 05:08:54 INFO - body = {'capabilities': {'alwaysMatch': {'moz:firefoxOptions': {'args': ['--profile',
[task 2022-11-09T05:08:54.008Z] 05:08:54 INFO - '/tmp/tmpx1ngnk8k.mozrunner'],
[task 2022-11-09T05:08:54.008Z] 05:08:54 INFO - 'binary': '/builds/worker/workspace/build/application/firefox/firefox',
[task 2022-11-09T05:08:54.009Z] 05:08:54 INFO - 'prefs': {'remote.active-protocols': 3}},
[task 2022-11-09T05:08:54.009Z] 05:08:54 INFO - 'webSocketUrl': True}}}
[task 2022-11-09T05:08:54.009Z] 05:08:54 INFO - self = <Session (disconnected)>
[task 2022-11-09T05:08:54.009Z] 05:08:54 INFO - tests/web-platform/tests/tools/webdriver/webdriver/client.py:616: in send_command
[task 2022-11-09T05:08:54.009Z] 05:08:54 INFO - session=self, timeout=timeout)
[task 2022-11-09T05:08:54.009Z] 05:08:54 INFO - body = {'capabilities': {'alwaysMatch': {'moz:firefoxOptions': {'args': ['--profile',
[task 2022-11-09T05:08:54.009Z] 05:08:54 INFO - '/tmp/tmpx1ngnk8k.mozrunner'],
[task 2022-11-09T05:08:54.010Z] 05:08:54 INFO - 'binary': '/builds/worker/workspace/build/application/firefox/firefox',
[task 2022-11-09T05:08:54.010Z] 05:08:54 INFO - 'prefs': {'remote.active-protocols': 3}},
[task 2022-11-09T05:08:54.010Z] 05:08:54 INFO - 'webSocketUrl': True}}}
[task 2022-11-09T05:08:54.010Z] 05:08:54 INFO - method = 'POST'
[task 2022-11-09T05:08:54.010Z] 05:08:54 INFO - self = <Session (disconnected)>
[task 2022-11-09T05:08:54.011Z] 05:08:54 INFO - timeout = None
[task 2022-11-09T05:08:54.011Z] 05:08:54 INFO - url = 'session'
[task 2022-11-09T05:08:54.011Z] 05:08:54 INFO - tests/web-platform/tests/tools/webdriver/webdriver/transport.py:234: in send
[task 2022-11-09T05:08:54.011Z] 05:08:54 INFO - response = self._request(method, uri, payload, headers, timeout=None)
[task 2022-11-09T05:08:54.011Z] 05:08:54 INFO - body = {'capabilities': {'alwaysMatch': {'moz:firefoxOptions': {'args': ['--profile',
[task 2022-11-09T05:08:54.011Z] 05:08:54 INFO - '/tmp/tmpx1ngnk8k.mozrunner'],
[task 2022-11-09T05:08:54.012Z] 05:08:54 INFO - 'binary': '/builds/worker/workspace/build/application/firefox/firefox',
[task 2022-11-09T05:08:54.012Z] 05:08:54 INFO - 'prefs': {'remote.active-protocols': 3}},
[task 2022-11-09T05:08:54.012Z] 05:08:54 INFO - 'webSocketUrl': True}}}
[task 2022-11-09T05:08:54.012Z] 05:08:54 INFO - codec_kwargs = {'session': <Session (disconnected)>}
[task 2022-11-09T05:08:54.012Z] 05:08:54 INFO - decoder = <class 'webdriver.protocol.Decoder'>
[task 2022-11-09T05:08:54.013Z] 05:08:54 INFO - encoder = <class 'webdriver.protocol.Encoder'>
[task 2022-11-09T05:08:54.013Z] 05:08:54 INFO - headers = None
[task 2022-11-09T05:08:54.013Z] 05:08:54 INFO - method = 'POST'
[task 2022-11-09T05:08:54.013Z] 05:08:54 INFO - payload = ('{"capabilities": {"alwaysMatch": {"moz:firefoxOptions": {"args": '
[task 2022-11-09T05:08:54.014Z] 05:08:54 INFO - '["--profile", "/tmp/tmpx1ngnk8k.mozrunner"], "binary": '
[task 2022-11-09T05:08:54.014Z] 05:08:54 INFO - '"/builds/worker/workspace/build/application/firefox/firefox", "prefs": '
[task 2022-11-09T05:08:54.014Z] 05:08:54 INFO - '{"remote.active-protocols": 3}}, "webSocketUrl": true}}}')
[task 2022-11-09T05:08:54.014Z] 05:08:54 INFO - self = <webdriver.transport.HTTPWireProtocol object at 0x7fd2fe5126a0>
[task 2022-11-09T05:08:54.014Z] 05:08:54 INFO - timeout = None
[task 2022-11-09T05:08:54.015Z] 05:08:54 INFO - uri = 'session'
[task 2022-11-09T05:08:54.015Z] 05:08:54 INFO - tests/web-platform/tests/tools/webdriver/webdriver/transport.py:251: in _request
<...>
[task 2022-11-09T05:08:54.140Z] 05:08:54 INFO - STDOUT: ============================== 1 failed in 6.96s ===============================
[task 2022-11-09T05:08:54.140Z] 05:08:54 INFO - queue closed
[task 2022-11-09T05:08:54.140Z] 05:08:54 INFO - PID 25305 | 1667970534092 geckodriver INFO Listening on 127.0.0.1:42986
[task 2022-11-09T05:08:54.141Z] 05:08:54 INFO - Starting runner
[task 2022-11-09T05:08:54.354Z] 05:08:54 INFO - TEST-START | /_mozilla/webdriver/new_session/binary.py
|
||
Updated•2 years ago
|
|
||
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
•