Closed
Bug 1803084
Opened 2 years ago
Closed 2 years ago
Intermittent testing/marionette/harness/marionette_harness/tests/unit/test_click_scrolling.py TestClickScrolling.test_should_not_scroll_elements_if_click_point_is_in_view | OSError: Process has been unexpectedly closed (Exit code: 0)
Categories
(Testing :: Marionette Client and Harness, defect, P5)
Testing
Marionette Client and Harness
Tracking
(Not tracked)
RESOLVED
DUPLICATE
of bug 1635776
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=398006487&repo=mozilla-central
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/Zix8_Kg0Tn6v-h9jLJnrHA/runs/0/artifacts/public/logs/live_backing.log
[task 2022-11-29T09:45:32.348Z] 09:45:32 INFO - TEST-PASS | testing/marionette/harness/marionette_harness/tests/unit/test_click_scrolling.py TestClickScrolling.test_scroll_radio_button_into_view | took 309ms
[task 2022-11-29T09:45:32.348Z] 09:45:32 INFO - TEST-START | testing/marionette/harness/marionette_harness/tests/unit/test_click_scrolling.py TestClickScrolling.test_should_not_scroll_elements_if_click_point_is_in_view
[task 2022-11-29T09:45:32.349Z] 09:45:32 INFO - 1669715132349 Marionette DEBUG Accepted connection 181 from 127.0.0.1:51160
[task 2022-11-29T09:45:32.350Z] 09:45:32 INFO - 1669715132350 Marionette DEBUG 181 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
[task 2022-11-29T09:45:32.351Z] 09:45:32 INFO - 1669715132351 Marionette DEBUG Waiting for initial application window
[task 2022-11-29T09:45:32.352Z] 09:45:32 INFO - 1669715132352 RemoteAgent TRACE [137] ProgressListener Start: expectNavigation=false resolveWhenStarted=false unloadTimeout=1600 waitForExplicitStart=false
[task 2022-11-29T09:45:32.352Z] 09:45:32 INFO - 1669715132352 RemoteAgent TRACE [137] ProgressListener Setting unload timer (1600ms)
[task 2022-11-29T09:45:32.352Z] 09:45:32 INFO - 1669715132352 RemoteAgent TRACE [137] Document already finished loading: data:text/html;charset=utf-8,%0A%20%20%20%20%20%20%20%20%20%20%3Cinput%20type%3D%22radio%22%20id%3D%22radio%22%20style%3D%22margin-top%3A%20105vh%3B%22%3E%0A%20%20%20%20%20%20%20%20
[task 2022-11-29T09:45:32.353Z] 09:45:32 INFO - 1669715132352 RemoteAgent TRACE [137] ProgressListener Stop: has error=false
[task 2022-11-29T09:45:32.356Z] 09:45:32 INFO - 1669715132355 Marionette DEBUG 181 <- [1,1,null,{"sessionId":"6653c3c0-6174-4b5c-a002-507ef162cfd9","capabilities":{"browserName":"firefox","browserVersion":"109.0a1","platformName":"windows","acceptInsecureCerts":false,"pageLoadStrategy":"normal","setWindowRect":true,"timeouts":{"implicit":0,"pageLoad":300000,"script":30000},"strictFileInteractability":true,"unhandledPromptBehavior":"dismiss and notify","moz:accessibilityChecks":false,"moz:buildID":"20221129084032","moz:headless":false,"moz:platformVersion":"10.0","moz:processID":5412,"moz:profile":"C:\\Users\\task_166971380511478\\AppData\\Local\\Temp\\tmpjkycfz9o.mozrunner","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true,"moz:windowless":false,"proxy":{}}}]
[task 2022-11-29T09:45:32.356Z] 09:45:32 INFO - 1669715132356 Marionette DEBUG 181 -> [0,2,"WebDriver:SetTimeouts",{"script":30000}]
[task 2022-11-29T09:45:32.357Z] 09:45:32 INFO - 1669715132357 Marionette DEBUG 181 <- [1,2,null,{"value":null}]
[task 2022-11-29T09:45:32.357Z] 09:45:32 INFO - 1669715132358 Marionette DEBUG 181 -> [0,3,"WebDriver:SetTimeouts",{"pageLoad":300000}]
[task 2022-11-29T09:45:32.358Z] 09:45:32 INFO - 1669715132358 Marionette DEBUG 181 <- [1,3,null,{"value":null}]
[task 2022-11-29T09:45:32.359Z] 09:45:32 INFO - 1669715132359 Marionette DEBUG 181 -> [0,4,"WebDriver:SetTimeouts",{"implicit":0}]
[task 2022-11-29T09:45:32.360Z] 09:45:32 INFO - 1669715132360 Marionette DEBUG 181 <- [1,4,null,{"value":null}]
[task 2022-11-29T09:45:32.361Z] 09:45:32 INFO - 1669715132361 Marionette DEBUG 181 -> [0,5,"WebDriver:Navigate",{"url":"http://127.0.0.1:49838/element_outside_viewport.html"}]
[task 2022-11-29T09:45:32.362Z] 09:45:32 INFO - [Parent 5412, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, false) failed with result 0x804B0051 (NS_ERROR_HOST_IS_IP_ADDRESS): file /builds/worker/checkouts/gecko/toolkit/components/antitracking/URLQueryStringStripper.cpp:150
[task 2022-11-29T09:45:32.389Z] 09:45:32 INFO - 1669715132389 Marionette TRACE Remoteness change detected. Set new top-level browsing context to 137
[task 2022-11-29T09:45:32.402Z] 09:45:32 INFO - 1669715132402 Marionette TRACE [137] Received event beforeunload for about:blank
[task 2022-11-29T09:45:32.415Z] 09:45:32 INFO - 1669715132414 Marionette TRACE [137] Received event pagehide for about:blank
[task 2022-11-29T09:45:32.449Z] 09:45:32 INFO - 1669715132449 Marionette TRACE [137] Received event DOMContentLoaded for http://127.0.0.1:49838/element_outside_viewport.html
[task 2022-11-29T09:45:32.454Z] 09:45:32 INFO - 1669715132454 Marionette TRACE [137] Received event pageshow for http://127.0.0.1:49838/element_outside_viewport.html
[task 2022-11-29T09:45:32.455Z] 09:45:32 INFO - 1669715132455 Marionette DEBUG 181 <- [1,5,null,{"value":null}]
[task 2022-11-29T09:45:32.456Z] 09:45:32 INFO - [Child 6876, Main Thread] WARNING: '!scrollbar', file /builds/worker/checkouts/gecko/widget/Theme.cpp:1105
[task 2022-11-29T09:45:32.458Z] 09:45:32 INFO - 1669715132460 Marionette DEBUG 181 -> [0,6,"WebDriver:ExecuteScript",{"script":"return [window.scrollX, window.scrollY];","args":[],"newSandbox":true,"sandbox":"default","line":65,"filename":"Z:\\task_166971380511478\\build\\tests\\marionette\\tests\\testing\\marionette\\harness\\marionette_harness\\tests\\unit\\test_click_scrolling.py"}]
[task 2022-11-29T09:45:32.467Z] 09:45:32 INFO - 1669715132467 Marionette TRACE [137] MarionetteCommands actor created for window id 68719476737
[task 2022-11-29T09:45:32.477Z] 09:45:32 INFO - DEBUG: Adding blocker Transaction (19) for phase protections.sqlite#0: waiting for clients
[task 2022-11-29T09:45:32.480Z] 09:45:32 INFO - DEBUG: Completed blocker Transaction (19) for phase protections.sqlite#0: waiting for clients
[task 2022-11-29T09:45:32.488Z] 09:45:32 INFO - [Child 6876, Main Thread] WARNING: '!scrollbar', file /builds/worker/checkouts/gecko/widget/Theme.cpp:1105
[task 2022-11-29T09:45:32.488Z] 09:45:32 INFO - 1669715132487 Marionette DEBUG 181 <- [1,6,null,{"value":[70,70]}]
[task 2022-11-29T09:45:32.489Z] 09:45:32 INFO - 1669715132489 Marionette DEBUG 181 -> [0,7,"WebDriver:FindElement",{"value":"top-50","using":"id"}]
[task 2022-11-29T09:45:32.498Z] 09:45:32 INFO - 1669715132506 Marionette DEBUG 181 <- [1,7,null,{"value":{"element-6066-11e4-a52e-4f735466cecf":"f6ad565e-f107-4fd3-8285-17bc66683d80"}}]
[task 2022-11-29T09:45:32.508Z] 09:45:32 INFO - 1669715132508 Marionette DEBUG 181 -> [0,8,"WebDriver:ElementClick",{"id":"f6ad565e-f107-4fd3-8285-17bc66683d80"}]
[task 2022-11-29T09:45:32.513Z] 09:45:32 INFO - 1669715132516 Marionette TRACE [137] Received event beforeunload for data:text/html;charset=utf-8,%0A%20%20%20%20%20%20%20%20%20%20%3Cinput%20type%3D%22radio%22%20id%3D%22radio%22%20style%3D%22margin-top%3A%20105vh%3B%22%3E%0A%20%20%20%20%20%20%20%20
[task 2022-11-29T09:45:32.517Z] 09:45:32 INFO - [Parent 5412, Main Thread] WARNING: WebProgress Ignored: no longer current window global: file /builds/worker/checkouts/gecko/dom/ipc/BrowserParent.cpp:3096
[task 2022-11-29T09:45:32.519Z] 09:45:32 INFO - 1669715132518 Marionette TRACE [137] Received event pagehide for data:text/html;charset=utf-8,%0A%20%20%20%20%20%20%20%20%20%20%3Cinput%20type%3D%22radio%22%20id%3D%22radio%22%20style%3D%22margin-top%3A%20105vh%3B%22%3E%0A%20%20%20%20%20%20%20%20
[task 2022-11-29T09:45:32.529Z] 09:45:32 INFO - [Child 1708, Main Thread] WARNING: IPC message 'PSessionStore::Msg_SessionStoreUpdate' discarded: actor cannot send: file /builds/worker/checkouts/gecko/ipc/glue/ProtocolUtils.cpp:504
[task 2022-11-29T09:45:32.531Z] 09:45:32 INFO - [Child 1708, Main Thread] WARNING: IPC message 'PSessionStore::Msg_SessionStoreUpdate' discarded: actor cannot send: file /builds/worker/checkouts/gecko/ipc/glue/ProtocolUtils.cpp:504
[task 2022-11-29T09:45:32.532Z] 09:45:32 INFO - DEBUG: Starting phase xpcom-will-shutdown
[task 2022-11-29T09:45:32.537Z] 09:45:32 INFO - [Child 1708, Main Thread] WARNING: IPC message 'PContent::Msg_StoreUserInteractionAsPermission' discarded: actor cannot send: file /builds/worker/checkouts/gecko/ipc/glue/ProtocolUtils.cpp:504
[task 2022-11-29T09:45:32.539Z] 09:45:32 INFO - DEBUG: Spinning the event loop
[task 2022-11-29T09:45:32.539Z] 09:45:32 INFO - DEBUG: Finished phase xpcom-will-shutdown
[task 2022-11-29T09:45:32.549Z] 09:45:32 INFO - 1669715132551 Marionette TRACE Received DOM event click for [object HTMLDivElement]
[task 2022-11-29T09:45:32.552Z] 09:45:32 INFO - [Child 6876, Main Thread] WARNING: '!scrollbar', file /builds/worker/checkouts/gecko/widget/Theme.cpp:1105
[task 2022-11-29T09:45:32.573Z] 09:45:32 INFO - [GPU 2080, Compositor] WARNING: bad Shmem: file /builds/worker/checkouts/gecko/ipc/glue/ProtocolUtils.cpp:446
[task 2022-11-29T09:45:32.573Z] 09:45:32 INFO - [GPU 2080, Compositor] WARNING: bad Shmem: file /builds/worker/checkouts/gecko/ipc/glue/ProtocolUtils.cpp:446
[task 2022-11-29T09:45:32.577Z] 09:45:32 INFO - DEBUG: Adding blocker UserInteractionTimer 1 for document 191ae6b7000 for phase xpcom-will-shutdown
[task 2022-11-29T09:45:32.605Z] 09:45:32 INFO - [Child 1708, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp:3387
[task 2022-11-29T09:45:32.607Z] 09:45:32 INFO - [Child 1708, Main Thread] WARNING: NS_ENSURE_TRUE(InitStaticMembers()) failed: file /builds/worker/workspace/obj-build/dist/include/mozilla/Preferences.h:129
[task 2022-11-29T09:45:32.616Z] 09:45:32 INFO - [Child 1708, Main Thread] WARNING: NS_ENSURE_TRUE(Preferences::InitStaticMembers()) failed: file /builds/worker/checkouts/gecko/modules/libpref/Preferences.cpp:4628
[task 2022-11-29T09:45:33.371Z] 09:45:33 INFO - DEBUG: Adding blocker ContentParent: id=258c26b3f00 for phase xpcom-will-shutdown
[task 2022-11-29T09:45:33.371Z] 09:45:33 INFO - DEBUG: Adding blocker ContentParent: id=258c26b3f00 for phase profile-before-change
[task 2022-11-29T09:45:33.373Z] 09:45:33 INFO - DEBUG: Adding blocker ContentParent: id=258c26b3f00 for phase quit-application-granted
[task 2022-11-29T09:45:44.281Z] 09:45:44 INFO - [Child 9180, Main Thread] WARNING: '!aContent->GetComposedDoc()', file /builds/worker/checkouts/gecko/layout/base/nsCSSFrameConstructor.cpp:8488
[task 2022-11-29T09:45:44.281Z] 09:45:44 INFO - [Child 6876, Main Thread] WARNING: '!aContent->GetComposedDoc()', file /builds/worker/checkouts/gecko/layout/base/nsCSSFrameConstructor.cpp:8488
[task 2022-11-29T09:45:44.284Z] 09:45:44 INFO - [Child 6876, Main Thread] WARNING: '!scrollbar', file /builds/worker/checkouts/gecko/widget/Theme.cpp:1105
[task 2022-11-29T09:45:44.284Z] 09:45:44 INFO - [Child 9180, Main Thread] WARNING: '!aContent->GetComposedDoc()', file /builds/worker/checkouts/gecko/layout/base/nsCSSFrameConstructor.cpp:8488
[task 2022-11-29T09:45:44.285Z] 09:45:44 INFO - [Child 9180, Main Thread] WARNING: '!aContent->GetComposedDoc()', file /builds/worker/checkouts/gecko/layout/base/nsCSSFrameConstructor.cpp:8488
[task 2022-11-29T09:45:44.286Z] 09:45:44 INFO - [Child 9180, Main Thread] WARNING: '!aContent->GetComposedDoc()', file /builds/worker/checkouts/gecko/layout/base/nsCSSFrameConstructor.cpp:8488
[task 2022-11-29T09:45:44.288Z] 09:45:44 INFO - [Child 9180, Main Thread] WARNING: '!aContent->GetComposedDoc()', file /builds/worker/checkouts/gecko/layout/base/nsCSSFrameConstructor.cpp:8488
[task 2022-11-29T09:45:44.291Z] 09:45:44 INFO - [Child 9180, Main Thread] WARNING: '!aContent->GetComposedDoc()', file /builds/worker/checkouts/gecko/layout/base/nsCSSFrameConstructor.cpp:8488
[task 2022-11-29T09:45:44.445Z] 09:45:44 INFO - DEBUG: Adding blocker OS.File: flush pending requests, warn about unclosed files, shut down service. for phase xpcom-will-shutdown
[task 2022-11-29T09:45:44.447Z] 09:45:44 INFO - DEBUG: Adding blocker OS.File: flush I/O queued before profileBeforeChange for phase profile-before-change
[task 2022-11-29T09:45:46.072Z] 09:45:46 INFO - DEBUG: Adding blocker SessionFile: Finish writing Session Restore data for phase IOUtils: waiting for profileBeforeChange IO to complete
[task 2022-11-29T09:45:46.081Z] 09:45:46 INFO - DEBUG: Completed blocker SessionFile: Finish writing Session Restore data for phase IOUtils: waiting for profileBeforeChange IO to complete
[task 2022-11-29T09:46:01.101Z] 09:46:01 INFO - DEBUG: Adding blocker SessionFile: Finish writing Session Restore data for phase IOUtils: waiting for profileBeforeChange IO to complete
[task 2022-11-29T09:46:01.109Z] 09:46:01 INFO - DEBUG: Completed blocker SessionFile: Finish writing Session Restore data for phase IOUtils: waiting for profileBeforeChange IO to complete
[task 2022-11-29T09:46:46.359Z] 09:46:46 INFO - [Parent 5412, Jump List] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80520012 (NS_ERROR_FILE_NOT_FOUND): file /builds/worker/checkouts/gecko/widget/windows/WinUtils.cpp:1076
[task 2022-11-29T09:47:14.458Z] 09:47:14 INFO - [2022-11-29T09:47:14Z WARN rkv::backend::impl_safe::environment] `load_ratio()` is irrelevant for this storage backend.
[task 2022-11-29T09:47:14.466Z] 09:47:14 INFO - console.error: (new Error("Polling for changes failed: The URI is malformed..", "resource://services-settings/remote-settings.js", 334))
[task 2022-11-29T09:47:28.658Z] 09:47:28 INFO - WARNING | IO Completion Port failed to signal process shutdown
[task 2022-11-29T09:47:28.658Z] 09:47:28 INFO - Parent process 2100 exited with children alive:
[task 2022-11-29T09:47:28.658Z] 09:47:28 INFO - PIDS: 2084, 5412, 2080, 3712, 9180, 6876, 9148, 8920, 6100
[task 2022-11-29T09:47:28.660Z] 09:47:28 INFO - Attempting to kill them, but no guarantee of success
[task 2022-11-29T09:51:32.511Z] 09:51:32 ERROR - TEST-UNEXPECTED-ERROR | testing/marionette/harness/marionette_harness/tests/unit/test_click_scrolling.py TestClickScrolling.test_should_not_scroll_elements_if_click_point_is_in_view | OSError: Process has been unexpectedly closed (Exit code: 0) (Reason: Connection timed out after 360.0s)
[task 2022-11-29T09:51:32.511Z] 09:51:32 INFO - Traceback (most recent call last):
[task 2022-11-29T09:51:32.511Z] 09:51:32 INFO - File "Z:\task_166971380511478\build\venv\lib\site-packages\marionette_harness\marionette_test\testcases.py", line 202, in run
[task 2022-11-29T09:51:32.512Z] 09:51:32 INFO - testMethod()
[task 2022-11-29T09:51:32.512Z] 09:51:32 INFO - File "Z:\task_166971380511478\build\tests\marionette\tests\testing\marionette\harness\marionette_harness\tests\unit\test_click_scrolling.py", line 68, in test_should_not_scroll_elements_if_click_point_is_in_view
[task 2022-11-29T09:51:32.513Z] 09:51:32 INFO - self.marionette.find_element(By.ID, "{0}-{1}".format(s, p)).click()
[task 2022-11-29T09:51:32.513Z] 09:51:32 INFO - File "Z:\task_166971380511478\build\venv\lib\site-packages\marionette_driver\marionette.py", line 261, in click
[task 2022-11-29T09:51:32.513Z] 09:51:32 INFO - self.marionette._send_message("WebDriver:ElementClick", {"id": self.id})
[task 2022-11-29T09:51:32.513Z] 09:51:32 INFO - File "Z:\task_166971380511478\build\venv\lib\site-packages\marionette_driver\decorators.py", line 37, in _
[task 2022-11-29T09:51:32.514Z] 09:51:32 INFO - m._handle_socket_failure()
[task 2022-11-29T09:51:32.514Z] 09:51:32 INFO - File "Z:\task_166971380511478\build\venv\lib\site-packages\marionette_driver\marionette.py", line 745, in _handle_socket_failure
[task 2022-11-29T09:51:32.514Z] 09:51:32 INFO - reraise(
[task 2022-11-29T09:51:32.514Z] 09:51:32 INFO - File "Z:\task_166971380511478\build\venv\lib\site-packages\six.py", line 702, in reraise
[task 2022-11-29T09:51:32.515Z] 09:51:32 INFO - raise value.with_traceback(tb)
[task 2022-11-29T09:51:32.515Z] 09:51:32 INFO - File "Z:\task_166971380511478\build\venv\lib\site-packages\marionette_driver\decorators.py", line 27, in _
[task 2022-11-29T09:51:32.515Z] 09:51:32 INFO - return func(*args, **kwargs)
[task 2022-11-29T09:51:32.516Z] 09:51:32 INFO - File "Z:\task_166971380511478\build\venv\lib\site-packages\marionette_driver\marionette.py", line 661, in _send_message
[task 2022-11-29T09:51:32.516Z] 09:51:32 INFO - msg = self.client.request(name, params)
[task 2022-11-29T09:51:32.516Z] 09:51:32 INFO - File "Z:\task_166971380511478\build\venv\lib\site-packages\marionette_driver\transport.py", line 383, in request
[task 2022-11-29T09:51:32.516Z] 09:51:32 INFO - return self.receive()
[task 2022-11-29T09:51:32.516Z] 09:51:32 INFO - File "Z:\task_166971380511478\build\venv\lib\site-packages\marionette_driver\transport.py", line 220, in receive
[task 2022-11-29T09:51:32.517Z] 09:51:32 INFO - raise socket.timeout(
[task 2022-11-29T09:51:32.517Z] 09:51:32 INFO - TEST-INFO took 360153ms
[task 2022-11-29T09:51:32.518Z] 09:51:32 INFO - Application command: Z:\task_166971380511478\build\application\firefox\firefox.exe -no-remote -marionette --wait-for-browser -profile C:\Users\task_166971380511478\AppData\Local\Temp\tmpjkycfz9o.mozrunner
[task 2022-11-29T09:51:32.702Z] 09:51:32 INFO - DEBUG: Adding blocker PermissionManager: Flushing data for phase xpcom-will-shutdown
[task 2022-11-29T09:51:32.774Z] 09:51:32 INFO - DEBUG: Adding blocker AddonManager: shutting down. for phase profile-before-change
[task 2022-11-29T09:51:32.814Z] 09:51:32 INFO - DEBUG: Adding blocker IOUtils Blocker (profile-before-change) for phase profile-before-change
[task 2022-11-29T09:51:32.815Z] 09:51:32 INFO - DEBUG: Adding blocker IOUtils Blocker (profile-before-change-telemetry) for phase profile-before-change-telemetry
[task 2022-11-29T09:51:32.815Z] 09:51:32 INFO - DEBUG: Adding blocker IOUtils Blocker (profile-before-change) for phase IOUtils: waiting for sendTelemetry IO to complete
[task 2022-11-29T09:51:32.815Z] 09:51:32 INFO - DEBUG: Adding blocker IOUtils Blocker (xpcom-will-shutdown) for phase xpcom-will-shutdown
[task 2022-11-29T09:51:32.816Z] 09:51:32 INFO - DEBUG: Adding blocker IOUtils Blocker (profile-before-change-telemetry) for phase IOUtils: waiting for xpcomWillShutdown IO to complete
[task 2022-11-29T09:51:32.834Z] 09:51:32 INFO - DEBUG: Adding blocker XPIProvider shutdown for phase quit-application-granted
[task 2022-11-29T09:51:32.835Z] 09:51:32 INFO - DEBUG: Adding blocker XPIProvider for phase AddonManager: Waiting for providers to shut down.
[task 2022-11-29T09:51:32.836Z] 09:51:32 INFO - DEBUG: Adding blocker ServiceWorkerRegistrar: Flushing data for phase profile-before-change
[task 2022-11-29T09:51:32.837Z] 09:51:32 INFO - DEBUG: Adding blocker CrashMonitor: Writing notifications to file after receiving profile-before-change and awaiting all checkpoints written for phase IOUtils: waiting for profileBeforeChange IO to complete
[task 2022-11-29T09:51:32.853Z] 09:51:32 INFO - DEBUG: Adding blocker TelemetryController: shutting down for phase profile-before-change-telemetry
[task 2022-11-29T09:51:32.870Z] 09:51:32 INFO - DEBUG: Adding blocker EnvironmentAddonBuilder for phase AddonManager: Waiting to start provider shutdown.
[task 2022-11-29T09:51:32.875Z] 09:51:32 INFO - DEBUG: Adding blocker RemoteSettingsClient - finish IDB access. for phase profile-before-change
[task 2022-11-29T09:51:32.878Z] 09:51:32 INFO - DEBUG: Adding blocker TerminatoryTelemetry: Waiting to submit telemetry for phase IOUtils: waiting for sendTelemetry IO to complete
[task 2022-11-29T09:51:32.881Z] 09:51:32 INFO - 1669715492881 Marionette INFO Marionette enabled
[task 2022-11-29T09:51:32.883Z] 09:51:32 INFO - [Parent 2536, Main Thread] WARNING: NS_ENSURE_SUCCESS_VOID(rv) failed with result 0x8000FFFF (NS_ERROR_UNEXPECTED): file /builds/worker/checkouts/gecko/toolkit/xre/nsAppRunner.cpp:2546
[task 2022-11-29T09:51:32.883Z] 09:51:32 INFO - 1669715492883 Marionette TRACE Received observer notification final-ui-startup
[task 2022-11-29T09:51:32.885Z] 09:51:32 INFO - 1669715492885 Marionette INFO Listening on port 2828
[task 2022-11-29T09:51:32.885Z] 09:51:32 INFO - 1669715492885 Marionette DEBUG Marionette is listening
[task 2022-11-29T09:51:32.939Z] 09:51:32 INFO - DEBUG: Adding blocker ClientManagerService: start destroying IPC actors early for phase xpcom-will-shutdown
[task 2022-11-29T09:51:32.971Z] 09:51:32 INFO - WARN: driver_utils.cpp:184 (GetVendorString): ! Unimplemented: GetVendorString(/builds/worker/checkouts/gecko/gfx/angle/checkout/src/libANGLE/renderer/driver_utils.cpp:184)
[task 2022-11-29T09:51:32.972Z] 09:51:32 INFO - WARN: driver_utils.cpp:184 (GetVendorString): ! Unimplemented: GetVendorString(/builds/worker/checkouts/gecko/gfx/angle/checkout/src/libANGLE/renderer/driver_utils.cpp:184)
[task 2022-11-29T09:51:32.972Z] 09:51:32 INFO - [GPU 4840, Renderer] WARNING: Failed to bind API to GL!: file /builds/worker/checkouts/gecko/gfx/gl/GLContextProviderEGL.cpp:629
[task 2022-11-29T09:51:32.973Z] 09:51:32 INFO - [GPU 4840, Renderer] WARNING: Failed to create GLContext from PBuffer: file /builds/worker/checkouts/gecko/gfx/gl/GLContextProviderEGL.cpp:1165
[task 2022-11-29T09:51:32.973Z] 09:51:32 INFO - [GPU 4840, Renderer] WARNING: Failed to create EGLContext with khr_rbab_attribs: file /builds/worker/checkouts/gecko/gfx/gl/GLContextProviderEGL.cpp:727
[task 2022-11-29T09:51:32.973Z] 09:51:32 INFO - Initializing context 0000018563D98000 surface 0000018562153EB0 on display 0000018563D3D400
[task 2022-11-29T09:51:32.973Z] 09:51:32 INFO - WARN: driver_utils.cpp:184 (GetVendorString): ! Unimplemented: GetVendorString(/builds/worker/checkouts/gecko/gfx/angle/checkout/src/libANGLE/renderer/driver_utils.cpp:184)
[task 2022-11-29T09:51:32.974Z] 09:51:32 INFO - WARN: driver_utils.cpp:184 (GetVendorString): ! Unimplemented: GetVendorString(/builds/worker/checkouts/gecko/gfx/angle/checkout/src/libANGLE/renderer/driver_utils.cpp:184)
[task 2022-11-29T09:51:32.974Z] 09:51:32 INFO - GL_VENDOR: Google Inc. (Unknown)
[task 2022-11-29T09:51:32.974Z] 09:51:32 INFO - mVendor: Unknown
[task 2022-11-29T09:51:32.974Z] 09:51:32 INFO - GL_RENDERER: ANGLE (Unknown, Microsoft Basic Render Driver Direct3D11 vs_5_0 ps_5_0, D3D11-10.0.19041.546)
[task 2022-11-29T09:51:32.975Z] 09:51:32 INFO - mRenderer: Microsoft Basic Render Driver
[task 2022-11-29T09:51:32.975Z] 09:51:32 INFO - mIsMesa: 0
[task 2022-11-29T09:51:32.975Z] 09:51:32 INFO - [GPU 4840, Renderer] WARNING: framebuffer_multisample marked as unsupported: file /builds/worker/checkouts/gecko/gfx/gl/GLContextFeatures.cpp:632
[task 2022-11-29T09:51:33.047Z] 09:51:33 INFO - 1669715493052 Marionette DEBUG Accepted connection 0 from 127.0.0.1:51172
[task 2022-11-29T09:51:33.069Z] 09:51:33 INFO - 1669715493069 Marionette DEBUG Closed connection 0
[task 2022-11-29T09:51:33.130Z] 09:51:33 INFO - DEBUG: Adding blocker MediaShutdownManager: shutdown for phase profile-before-change
[task 2022-11-29T09:51:33.231Z] 09:51:33 INFO - 1669715493237 Marionette DEBUG Accepted connection 1 from 127.0.0.1:51175
[task 2022-11-29T09:51:33.241Z] 09:51:33 INFO - 1669715493248 Marionette DEBUG Closed connection 1
[task 2022-11-29T09:51:33.249Z] 09:51:33 INFO - 1669715493249 Marionette DEBUG Accepted connection 2 from 127.0.0.1:51176
[task 2022-11-29T09:51:33.286Z] 09:51:33 INFO - 1669715493286 Marionette DEBUG 2 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
[task 2022-11-29T09:51:33.290Z] 09:51:33 INFO - 1669715493289 Marionette DEBUG Waiting for initial application window
[task 2022-11-29T09:51:33.362Z] 09:51:33 INFO - DEBUG: Adding blocker ContentParent: id=21eb0cce000 for phase xpcom-will-shutdown
[task 2022-11-29T09:51:33.369Z] 09:51:33 INFO - DEBUG: Adding blocker ContentParent: id=21eb0cce000 for phase profile-before-change
[task 2022-11-29T09:51:33.369Z] 09:51:33 INFO - DEBUG: Adding blocker ContentParent: id=21eb0cce000 for phase quit-application-granted
[task 2022-11-29T09:51:33.373Z] 09:51:33 INFO - DEBUG: Adding blocker SitePermsAddonProvider for phase AddonManager: Waiting for providers to shut down.
[task 2022-11-29T09:51:33.376Z] 09:51:33 INFO - DEBUG: Adding blocker GMPProvider for phase AddonManager: Waiting for providers to shut down.
[task 2022-11-29T09:51:33.464Z] 09:51:33 INFO - DEBUG: Adding blocker ServiceWorkerShutdownBlocker: shutting down Service Workers for phase profile-change-teardown
[task 2022-11-29T09:51:33.519Z] 09:51:33 INFO - [Parent 2536, Main Thread] WARNING: NS_ENSURE_TRUE(mPresShell) failed: file /builds/worker/checkouts/gecko/layout/generic/nsFrameSelection.cpp:1606
[task 2022-11-29T09:51:33.556Z] 09:51:33 INFO - [Parent 2536, Main Thread] WARNING: NS_ENSURE_TRUE(mPresShell) failed: file /builds/worker/checkouts/gecko/layout/generic/nsFrameSelection.cpp:1606
[task 2022-11-29T09:51:33.578Z] 09:51:33 INFO - DEBUG: Adding blocker Sqlite.sys.mjs shutdown blocker for phase profile-before-change
[task 2022-11-29T09:51:33.578Z] 09:51:33 INFO - DEBUG: Adding blocker content-prefs.sqlite#0: waiting for shutdown for phase Sqlite.sys.mjs: wait until all connections are closed
[task 2022-11-29T09:51:33.578Z] 09:51:33 INFO - DEBUG: Adding blocker Closing ContentPrefService2 connection. for phase Sqlite.sys.mjs: wait until all clients have completed their task
[task 2022-11-29T09:51:33.581Z] 09:51:33 INFO - DEBUG: Adding blocker Transaction (0) for phase content-prefs.sqlite#0: waiting for clients
[task 2022-11-29T09:51:33.584Z] 09:51:33 INFO - DEBUG: Completed blocker Transaction (0) for phase content-prefs.sqlite#0: waiting for clients
[task 2022-11-29T09:51:34.059Z] 09:51:34 INFO - [Parent 2536, Main Thread] WARNING: NS_ENSURE_TRUE(mPresShell) failed: file /builds/worker/checkouts/gecko/layout/generic/nsFrameSelection.cpp:1606
[task 2022-11-29T09:51:34.110Z] 09:51:34 INFO - DEBUG: Adding blocker PageActions: purging unregistered actions from cache for phase profile-before-change
[task 2022-11-29T09:51:34.115Z] 09:51:34 INFO - DEBUG: Adding blocker Places Clients shutdown for phase profile-change-teardown
[task 2022-11-29T09:51:34.120Z] 09:51:34 INFO - DEBUG: Adding blocker Places Connection shutdown for phase profile-before-change
[task 2022-11-29T09:51:34.125Z] 09:51:34 INFO - DEBUG: Adding blocker JSON store: writing data for phase IOUtils: waiting for profileBeforeChange IO to complete
[task 2022-11-29T09:51:34.179Z] 09:51:34 INFO - DEBUG: Adding blocker sanitize.js: Sanitize on shutdown for phase Places Clients shutdown
[task 2022-11-29T09:51:34.250Z] 09:51:34 INFO - DEBUG: Adding blocker ContentParent: id=21eb2b5c500 for phase xpcom-will-shutdown
[task 2022-11-29T09:51:34.256Z] 09:51:34 INFO - DEBUG: Adding blocker ContentParent: id=21eb2b5c500 for phase profile-before-change
[task 2022-11-29T09:51:34.256Z] 09:51:34 INFO - DEBUG: Adding blocker ContentParent: id=21eb2b5c500 for phase quit-application-granted
[task 2022-11-29T09:51:34.261Z] 09:51:34 INFO - DEBUG: Adding blocker Transaction (1) for phase content-prefs.sqlite#0: waiting for clients
[task 2022-11-29T09:51:34.262Z] 09:51:34 INFO - DEBUG: Adding blocker Remote Settings profile-before-change for phase profile-before-change
[task 2022-11-29T09:51:34.318Z] 09:51:34 INFO - DEBUG: Adding blocker JSON store: writing data for phase IOUtils: waiting for profileBeforeChange IO to complete
[task 2022-11-29T09:51:34.324Z] 09:51:34 INFO - Couldn't convert chrome URL: chrome://branding/locale/brand.properties
[task 2022-11-29T09:51:34.324Z] 09:51:34 INFO - [Child 3588, Main Thread] WARNING: Could not get the program name for a cubeb stream.: 'NS_SUCCEEDED(rv)', file /builds/worker/checkouts/gecko/dom/media/CubebUtils.cpp:429
[task 2022-11-29T09:51:34.359Z] 09:51:34 INFO - [Parent 2536, 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-29T09:51:34.360Z] 09:51:34 INFO - DEBUG: Adding blocker JSON store: writing data for phase IOUtils: waiting for profileBeforeChange IO to complete
[task 2022-11-29T09:51:34.368Z] 09:51:34 INFO - DEBUG: Completed blocker Transaction (1) for phase content-prefs.sqlite#0: waiting for clients
[task 2022-11-29T09:51:34.454Z] 09:51:34 INFO - DEBUG: Adding blocker ContentParent: id=21eb2b5f200 for phase xpcom-will-shutdown
[task 2022-11-29T09:51:34.459Z] 09:51:34 INFO - DEBUG: Adding blocker ContentParent: id=21eb2b5f200 for phase profile-before-change
[task 2022-11-29T09:51:34.459Z] 09:51:34 INFO - DEBUG: Adding blocker ContentParent: id=21eb2b5f200 for phase quit-application-granted
[task 2022-11-29T09:51:34.535Z] 09:51:34 INFO - DEBUG: Adding blocker places.sqlite#1: waiting for shutdown for phase Sqlite.sys.mjs: wait until all connections are closed
[task 2022-11-29T09:51:34.535Z] 09:51:34 INFO - DEBUG: Adding blocker Places Expiration: shutdown for phase Places Connection shutdown
[task 2022-11-29T09:51:34.545Z] 09:51:34 INFO - DEBUG: Adding blocker PlacesUtils wrapped connection closing as part of Places shutdown for phase Places Connection shutdown
[task 2022-11-29T09:51:34.548Z] 09:51:34 INFO - DEBUG: Adding blocker PlacesUtils wrapped connection must be closed before Sqlite.sys.mjs for phase Sqlite.sys.mjs: wait until all clients have completed their task
[task 2022-11-29T09:51:34.549Z] 09:51:34 INFO - DEBUG: Adding blocker places.sqlite#1: PlacesExpiration.jsm: setup (0) for phase places.sqlite#1: waiting for clients
[task 2022-11-29T09:51:34.552Z] 09:51:34 INFO - DEBUG: Adding blocker places.sqlite#0: waiting for shutdown for phase Sqlite.sys.mjs: wait until all connections are closed
[task 2022-11-29T09:51:34.552Z] 09:51:34 INFO - DEBUG: Adding blocker PlacesUtils read-only connection closing as part of Places shutdown for phase Places Connection shutdown
[task 2022-11-29T09:51:34.553Z] 09:51:34 INFO - DEBUG: Adding blocker PlacesUtils read-only connection must be closed before Sqlite.sys.mjs for phase Sqlite.sys.mjs: wait until all clients have completed their task
[task 2022-11-29T09:51:34.556Z] 09:51:34 INFO - [Child 7412, Main Thread] WARNING: Fallback to FallbackRenderer: file /builds/worker/checkouts/gecko/dom/ipc/BrowserChild.cpp:2822
[task 2022-11-29T09:51:34.566Z] 09:51:34 INFO - DEBUG: Completed blocker places.sqlite#1: PlacesExpiration.jsm: setup (0) for phase places.sqlite#1: waiting for clients
[task 2022-11-29T09:51:34.570Z] 09:51:34 INFO - [Child 7412, Main Thread] WARNING: Fallback to FallbackRenderer: file /builds/worker/checkouts/gecko/dom/ipc/BrowserChild.cpp:2822
[task 2022-11-29T09:51:34.576Z] 09:51:34 INFO - [Child 7412, Main Thread] WARNING: Fallback to FallbackRenderer: file /builds/worker/checkouts/gecko/dom/ipc/BrowserChild.cpp:2822
[task 2022-11-29T09:51:34.578Z] 09:51:34 INFO - [Child 7412, Main Thread] WARNING: Fallback to FallbackRenderer: file /builds/worker/checkouts/gecko/dom/ipc/BrowserChild.cpp:2822
[task 2022-11-29T09:51:34.587Z] 09:51:34 INFO - [Child 7412, Main Thread] WARNING: Fallback to FallbackRenderer: file /builds/worker/checkouts/gecko/dom/ipc/BrowserChild.cpp:2822
[task 2022-11-29T09:51:34.591Z] 09:51:34 INFO - DEBUG: Adding blocker Search service: shutting down for phase IOUtils: waiting for profileBeforeChange IO to complete
[task 2022-11-29T09:51:34.594Z] 09:51:34 INFO - [Child 7412, Main Thread] WARNING: Fallback to FallbackRenderer: file /builds/worker/checkouts/gecko/dom/ipc/BrowserChild.cpp:2822
[task 2022-11-29T09:51:34.609Z] 09:51:34 INFO - console.error: (new SyntaxError("The URI is malformed.", (void 0), 133))
[task 2022-11-29T09:51:34.721Z] 09:51:34 INFO - DEBUG: Adding blocker JSON store: writing data for phase IOUtils: waiting for profileBeforeChange IO to complete
[task 2022-11-29T09:51:34.731Z] 09:51:34 INFO - [Parent 2536, BgIOThreadPool #2] WARNING: 'GetLastError() != ERROR_FILE_NOT_FOUND', file /builds/worker/checkouts/gecko/browser/components/shell/nsWindowsShellService.cpp:1646
[task 2022-11-29T09:51:34.733Z] 09:51:34 INFO - [Parent 2536, BgIOThreadPool #2] WARNING: 'GetLastError() != ERROR_FILE_NOT_FOUND', file /builds/worker/checkouts/gecko/browser/components/shell/nsWindowsShellService.cpp:1646
[task 2022-11-29T09:51:34.792Z] 09:51:34 INFO - console.error: (new SyntaxError("The URI is malformed.", (void 0), 133))
[task 2022-11-29T09:51:34.797Z] 09:51:34 INFO - console.error: (new SyntaxError("The URI is malformed.", (void 0), 133))
[task 2022-11-29T09:51:34.802Z] 09:51:34 INFO - console.error: (new SyntaxError("The URI is malformed.", (void 0), 133))
[task 2022-11-29T09:51:34.805Z] 09:51:34 INFO - console.error: (new SyntaxError("The URI is malformed.", (void 0), 133))
[task 2022-11-29T09:51:34.843Z] 09:51:34 INFO - DEBUG: Adding blocker ContentParent: id=21eaeb06800 for phase xpcom-will-shutdown
[task 2022-11-29T09:51:34.844Z] 09:51:34 INFO - DEBUG: Adding blocker ContentParent: id=21eaeb06800 for phase profile-before-change
[task 2022-11-29T09:51:34.844Z] 09:51:34 INFO - DEBUG: Adding blocker ContentParent: id=21eaeb06800 for phase quit-application-granted
[task 2022-11-29T09:51:34.846Z] 09:51:34 INFO - DEBUG: Adding blocker ContentParent: id=21eb33ebd00 for phase xpcom-will-shutdown
[task 2022-11-29T09:51:34.847Z] 09:51:34 INFO - DEBUG: Adding blocker ContentParent: id=21eb33ebd00 for phase profile-before-change
[task 2022-11-29T09:51:34.847Z] 09:51:34 INFO - DEBUG: Adding blocker ContentParent: id=21eb33ebd00 for phase quit-application-granted
[task 2022-11-29T09:51:34.919Z] 09:51:34 INFO - DEBUG: Adding blocker ContentParent: id=21eb33ec700 for phase xpcom-will-shutdown
[task 2022-11-29T09:51:34.919Z] 09:51:34 INFO - DEBUG: Adding blocker ContentParent: id=21eb33ec700 for phase profile-before-change
[task 2022-11-29T09:51:34.919Z] 09:51:34 INFO - DEBUG: Adding blocker ContentParent: id=21eb33ec700 for phase quit-application-granted
[task 2022-11-29T09:51:34.944Z] 09:51:34 INFO - DEBUG: Adding blocker DownloadAutoSaveView: writing data for phase profile-before-change
[task 2022-11-29T09:51:35.088Z] 09:51:35 INFO - 1669715495095 Marionette TRACE Received observer notification browser-idle-startup-tasks-finished
[task 2022-11-29T09:51:35.096Z] 09:51:35 INFO - DEBUG: Adding blocker ScriptPreloader: Saving bytecode cache for phase xpcom-will-shutdown
[task 2022-11-29T09:51:35.098Z] 09:51:35 INFO - 1669715495104 RemoteAgent TRACE [3] ProgressListener Start: expectNavigation=false resolveWhenStarted=false unloadTimeout=1600 waitForExplicitStart=false
[task 2022-11-29T09:51:35.105Z] 09:51:35 INFO - 1669715495104 RemoteAgent TRACE [3] ProgressListener Setting unload timer (1600ms)
[task 2022-11-29T09:51:35.105Z] 09:51:35 INFO - 1669715495105 RemoteAgent TRACE [3] Document already finished loading: about:blank
[task 2022-11-29T09:51:35.105Z] 09:51:35 INFO - 1669715495105 RemoteAgent TRACE [3] ProgressListener Stop: has error=false
[task 2022-11-29T09:51:35.119Z] 09:51:35 INFO - 1669715495117 Marionette DEBUG 2 <- [1,1,null,{"sessionId":"adf7b269-efc1-40f2-b373-7c081f07042c","capabilities":{"browserName":"firefox","browserVersion":"109.0a1","platformName":"windows","acceptInsecureCerts":false,"pageLoadStrategy":"normal","setWindowRect":true,"timeouts":{"implicit":0,"pageLoad":300000,"script":30000},"strictFileInteractability":true,"unhandledPromptBehavior":"dismiss and notify","moz:accessibilityChecks":false,"moz:buildID":"20221129084032","moz:headless":false,"moz:platformVersion":"10.0","moz:processID":2536,"moz:profile":"C:\\Users\\task_166971380511478\\AppData\\Local\\Temp\\tmpjkycfz9o.mozrunner","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true,"moz:windowless":false,"proxy":{}}}]
[task 2022-11-29T09:51:35.144Z] 09:51:35 INFO - 1669715495143 Marionette DEBUG 2 -> [0,2,"WebDriver:DeleteSession",{}]
[task 2022-11-29T09:51:35.149Z] 09:51:35 INFO - 1669715495149 Marionette DEBUG 2 <- [1,2,null,{"value":null}]
[task 2022-11-29T09:51:35.156Z] 09:51:35 INFO - TEST-START | testing/marionette/harness/marionette_harness/tests/unit/test_click_scrolling.py TestClickScrolling.test_should_scroll_to_click_on_an_element_hidden_by_overflow
|
||
Updated•2 years ago
|
|
||
Updated•2 years ago
|
Product: Testing → Remote Protocol
|
|
||
Comment 2•2 years ago
|
||
Moving bug to Testing::Marionette Client and Harness component per bug 1815831.
Component: Marionette → Marionette Client and Harness
Product: Remote Protocol → Testing
You need to log in
before you can comment on or make changes to this bug.
Description
•