Filed by: sstanca [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=410610819&repo=mozilla-central
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/YRodtOl5RJCQimTiF80usw/runs/0/artifacts/public/logs/live_backing.log

[task 2023-03-29T04:05:20.884Z] 04:05:20     INFO - TEST-START | testing/marionette/harness/marionette_harness/tests/unit/test_click.py TestClick.test_clicking_on_a_multiline_link
[task 2023-03-29T04:05:20.885Z] 04:05:20     INFO -  1680062720884	Marionette	DEBUG	Accepted connection 29 from 127.0.0.1:38942
[task 2023-03-29T04:05:20.885Z] 04:05:20     INFO -  1680062720884	Marionette	DEBUG	Closed connection 28
[task 2023-03-29T04:05:20.890Z] 04:05:20     INFO -  1680062720890	Marionette	DEBUG	29 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
[task 2023-03-29T04:05:20.892Z] 04:05:20     INFO -  1680062720892	Marionette	DEBUG	Waiting for initial application window
[task 2023-03-29T04:05:20.894Z] 04:05:20     INFO -  1680062720894	RemoteAgent	TRACE	[9] ProgressListener Start: expectNavigation=false resolveWhenStarted=false unloadTimeout=3200 waitForExplicitStart=false
[task 2023-03-29T04:05:20.895Z] 04:05:20     INFO -  1680062720895	RemoteAgent	TRACE	[9] ProgressListener Setting unload timer (3200ms)
[task 2023-03-29T04:05:20.896Z] 04:05:20     INFO -  1680062720895	RemoteAgent	TRACE	[9] Document already finished loading: about:blank
[task 2023-03-29T04:05:20.896Z] 04:05:20     INFO -  1680062720896	RemoteAgent	TRACE	[9] ProgressListener Stop: has error=false
[task 2023-03-29T04:05:20.900Z] 04:05:20     INFO -  1680062720899	Marionette	DEBUG	29 <- [1,1,null,{"sessionId":"98f094d9-8622-42f5-b6ba-1732de8db82f","capabilities":{"browserName":"firefox","browserVersion":"113.0a1","platformName":"linux","acceptInsecureCerts":false,"pageLoadStrategy":"normal","setWindowRect":true,"timeouts":{"implicit":0,"pageLoad":300000,"script":30000},"strictFileInteractability":true,"unhandledPromptBehavior":"dismiss and notify","moz:accessibilityChecks":false,"moz:buildID":"20230329030858","moz:headless":false,"moz:platformVersion":"4.4.0-1014-aws","moz:processID":3513,"moz:profile":"/tmp/tmps6_5hj3o.mozrunner","moz:shutdownTimeout":180000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true,"moz:windowless":false,"proxy":{}}}]
[task 2023-03-29T04:05:20.904Z] 04:05:20     INFO -  1680062720903	Marionette	DEBUG	29 -> [0,2,"WebDriver:SetTimeouts",{"script":30000}]
[task 2023-03-29T04:05:20.905Z] 04:05:20     INFO -  1680062720904	Marionette	DEBUG	29 <- [1,2,null,{"value":null}]
[task 2023-03-29T04:05:20.909Z] 04:05:20     INFO -  1680062720908	Marionette	DEBUG	29 -> [0,3,"WebDriver:SetTimeouts",{"pageLoad":300000}]
[task 2023-03-29T04:05:20.910Z] 04:05:20     INFO -  1680062720910	Marionette	DEBUG	29 <- [1,3,null,{"value":null}]
[task 2023-03-29T04:05:20.913Z] 04:05:20     INFO -  1680062720913	Marionette	DEBUG	29 -> [0,4,"WebDriver:SetTimeouts",{"implicit":0}]
[task 2023-03-29T04:05:20.914Z] 04:05:20     INFO -  1680062720914	Marionette	DEBUG	29 <- [1,4,null,{"value":null}]
[task 2023-03-29T04:05:20.916Z] 04:05:20     INFO -  1680062720915	Marionette	DEBUG	29 -> [0,5,"Marionette:GetContext",{}]
[task 2023-03-29T04:05:20.917Z] 04:05:20     INFO -  1680062720916	Marionette	DEBUG	29 <- [1,5,null,{"value":"content"}]
[task 2023-03-29T04:05:20.920Z] 04:05:20     INFO -  1680062720919	Marionette	DEBUG	29 -> [0,6,"Marionette:SetContext",{"value":"chrome"}]
[task 2023-03-29T04:05:20.921Z] 04:05:20     INFO -  1680062720921	Marionette	DEBUG	29 <- [1,6,null,{"value":null}]
<...>
[task 2023-03-29T04:10:21.112Z] 04:10:21     INFO -  1680063021111	Marionette	DEBUG	30 <- [1,2,{"error":"timeout","message":"TimedPromise timed out after 300000 ms","stacktrace":"RemoteError@chrome://remote/content/shared/RemoteError.sys.mjs:8:8\nWebDriverError@chrome://remote/content/shared/webdriver/Er ... or@chrome://remote/content/shared/webdriver/Errors.sys.mjs:492:5\nbail@chrome://remote/content/marionette/sync.sys.mjs:211:19\n"},null]
[task 2023-03-29T04:10:21.114Z] 04:10:21     INFO -  1680063021113	Marionette	DEBUG	30 -> [0,3,"Marionette:GetContext",{}]
[task 2023-03-29T04:10:21.114Z] 04:10:21     INFO -  1680063021114	Marionette	DEBUG	30 <- [1,3,null,{"value":"content"}]
[task 2023-03-29T04:10:21.116Z] 04:10:21     INFO -  1680063021116	Marionette	DEBUG	30 -> [0,4,"Marionette:SetContext",{"value":"chrome"}]
[task 2023-03-29T04:10:21.117Z] 04:10:21     INFO -  1680063021116	Marionette	DEBUG	30 <- [1,4,null,{"value":null}]
[task 2023-03-29T04:10:21.118Z] 04:10:21     INFO -  1680063021118	Marionette	DEBUG	30 -> [0,5,"WebDriver:TakeScreenshot",{"id":null,"full":true,"hash":false,"scroll":true}]
[task 2023-03-29T04:10:21.125Z] 04:10:21     INFO -  1680063021124	RemoteAgent	TRACE	WebDriverProcessData actor created for PID 3513
[task 2023-03-29T04:10:21.127Z] 04:10:21     INFO -  1680063021126	Marionette	TRACE	[1] MarionetteCommands actor created for window id 2
[task 2023-03-29T04:10:21.184Z] 04:10:21     INFO -  1680063021183	Marionette	DEBUG	30 <- [1,5,null,{"value":"iVBORw0KGgoAAAANSUhEUgAABQAAAAQQCAYAAAC9RfbYAAAgAElEQVR4XuzdC5hkZ1kn8K+np+eeCRBIhhB2IYFggCQIBLmpCISbAoqKChFU5BbEh4uANxYQkAXks ... AAQIEXrSAAPiiz+vhCBA4IiAAHlHyGgIECBAgQIAAAQIECBCoCgiA1cvZmwCBiwkIgBej9EYECBAgQIAAAQIECBAgcIUC/wWnDkETT8h2PQAAAABJRU5ErkJggg=="}]
[task 2023-03-29T04:10:21.187Z] 04:10:21     INFO -  1680063021186	Marionette	DEBUG	30 -> [0,6,"Marionette:SetContext",{"value":"content"}]
[task 2023-03-29T04:10:21.188Z] 04:10:21     INFO -  1680063021187	Marionette	DEBUG	30 <- [1,6,null,{"value":null}]
[task 2023-03-29T04:10:21.188Z] 04:10:21     INFO -  1680063021188	Marionette	DEBUG	30 -> [0,7,"Marionette:GetContext",{}]
[task 2023-03-29T04:10:21.190Z] 04:10:21     INFO -  1680063021188	Marionette	DEBUG	30 <- [1,7,null,{"value":"content"}]
[task 2023-03-29T04:10:21.190Z] 04:10:21     INFO -  1680063021190	Marionette	DEBUG	30 -> [0,8,"Marionette:SetContext",{"value":"content"}]
[task 2023-03-29T04:10:21.191Z] 04:10:21     INFO -  1680063021190	Marionette	DEBUG	30 <- [1,8,null,{"value":null}]
[task 2023-03-29T04:10:21.191Z] 04:10:21     INFO -  1680063021191	Marionette	DEBUG	30 -> [0,9,"WebDriver:GetPageSource",{}]
[task 2023-03-29T04:16:21.260Z] 04:16:21     INFO -  1680063381259	Marionette	TRACE	[1] MarionetteCommands actor destroyed for window id 2
[task 2023-03-29T04:16:21.260Z] 04:16:21     INFO -  1680063381260	Marionette	TRACE	Retrying "getPageSource", attempt: 1
[task 2023-03-29T04:16:21.263Z] 04:16:21     INFO -  1680063381261	Marionette	DEBUG	30 <- [1,9,{"error":"unknown error","message":"NotFoundError: WindowGlobalParent.getActor: No such JSWindowActor 'MarionetteCommands'","stacktrace":"getMarionetteCommandsActorProxy/get/<@chrome://remote/content/marionette/actors/MarionetteCommandsParent.sys.mjs:309:65\nunreg ... e/content/marionette/transport.sys.mjs:217:18\nonInputStreamReady@chrome://remote/content/marionette/transport.sys.mjs:371:14\n"},null]
[task 2023-03-29T04:16:21.263Z] 04:16:21     INFO -  Marionette threw an error: NotFoundError: WindowGlobalParent.getActor: No such JSWindowActor 'MarionetteCommands'
[task 2023-03-29T04:16:21.263Z] 04:16:21     INFO -  getMarionetteCommandsActorProxy/get/<@chrome://remote/content/marionette/actors/MarionetteCommandsParent.sys.mjs:309:65
[task 2023-03-29T04:16:21.263Z] 04:16:21     INFO -  unregisterCommandsActor@chrome://remote/content/marionette/actors/MarionetteCommandsParent.sys.mjs:380:15
[task 2023-03-29T04:16:21.263Z] 04:16:21     INFO -  GeckoDriver.prototype.deleteSession@chrome://remote/content/marionette/driver.sys.mjs:2377:8
[task 2023-03-29T04:16:21.263Z] 04:16:21     INFO -  onClosed@chrome://remote/content/marionette/server.sys.mjs:205:17
[task 2023-03-29T04:16:21.263Z] 04:16:21     INFO -  close@chrome://remote/content/marionette/transport.sys.mjs:217:18
[task 2023-03-29T04:16:21.263Z] 04:16:21     INFO -  onInputStreamReady@chrome://remote/content/marionette/transport.sys.mjs:371:14
[task 2023-03-29T04:16:21.264Z] 04:16:21     INFO -  console.error: "Marionette threw an error: NotFoundError: WindowGlobalParent.getActor: No such JSWindowActor 'MarionetteCommands'\ngetMarionetteCommandsActorProxy/get/<@chrome://remote/content/marionette/actors/MarionetteCommandsParent.sys.mjs:309:65\nunregisterCommandsActor@chrome://remote/content/marionette/actors/MarionetteCommandsParent.sys.mjs:380:15\nGeckoDriver.prototype.deleteSession@chrome://remote/content/marionette/driver.sys.mjs:2377:8\nonClosed@chrome://remote/content/marionette/server.sys.mjs:205:17\nclose@chrome://remote/content/marionette/transport.sys.mjs:217:18\nonInputStreamReady@chrome://remote/content/marionette/transport.sys.mjs:371:14\n"
[task 2023-03-29T04:16:21.264Z] 04:16:21     INFO -  1680063381263	Marionette	DEBUG	Closed connection 30
[task 2023-03-29T04:19:32.342Z] 04:19:32  WARNING - Failed to gather test failure debug: Please start a session
[task 2023-03-29T04:19:32.377Z] 04:19:32     INFO - TEST-UNEXPECTED-ERROR | testing/marionette/harness/marionette_harness/tests/unit/test_click.py TestClick.test_clicking_on_a_multiline_link | marionette_driver.errors.TimeoutException: TimedPromise timed out after 300000 ms
[task 2023-03-29T04:19:32.377Z] 04:19:32     INFO - stacktrace:
[task 2023-03-29T04:19:32.377Z] 04:19:32     INFO - 	RemoteError@chrome://remote/content/shared/RemoteError.sys.mjs:8:8
[task 2023-03-29T04:19:32.377Z] 04:19:32     INFO - 	WebDriverError@chrome://remote/content/shared/webdriver/Errors.sys.mjs:182:5
[task 2023-03-29T04:19:32.377Z] 04:19:32     INFO - 	TimeoutError@chrome://remote/content/shared/webdriver/Errors.sys.mjs:492:5
[task 2023-03-29T04:19:32.378Z] 04:19:32     INFO - 	bail@chrome://remote/content/marionette/sync.sys.mjs:211:19
[task 2023-03-29T04:19:32.378Z] 04:19:32     INFO - Traceback (most recent call last):
[task 2023-03-29T04:19:32.378Z] 04:19:32     INFO -   File "/builds/worker/workspace/build/venv/lib/python3.7/site-packages/marionette_harness/marionette_test/testcases.py", line 198, in run
[task 2023-03-29T04:19:32.378Z] 04:19:32     INFO -     testMethod()
[task 2023-03-29T04:19:32.378Z] 04:19:32     INFO -   File "/builds/worker/workspace/build/tests/marionette/tests/testing/marionette/harness/marionette_harness/tests/unit/test_click.py", line 135, in test_clicking_on_a_multiline_link
[task 2023-03-29T04:19:32.378Z] 04:19:32     INFO -     self.marionette.navigate(test_html)
[task 2023-03-29T04:19:32.378Z] 04:19:32     INFO -   File "/builds/worker/workspace/build/venv/lib/python3.7/site-packages/marionette_driver/marionette.py", line 1632, in navigate
[task 2023-03-29T04:19:32.378Z] 04:19:32     INFO -     self._send_message("WebDriver:Navigate", {"url": url})
[task 2023-03-29T04:19:32.378Z] 04:19:32     INFO -   File "/builds/worker/workspace/build/venv/lib/python3.7/site-packages/marionette_driver/decorators.py", line 24, in _
[task 2023-03-29T04:19:32.378Z] 04:19:32     INFO -     return func(*args, **kwargs)
[task 2023-03-29T04:19:32.378Z] 04:19:32     INFO -   File "/builds/worker/workspace/build/venv/lib/python3.7/site-packages/marionette_driver/marionette.py", line 703, in _send_message
[task 2023-03-29T04:19:32.378Z] 04:19:32     INFO -     self._handle_error(err)
[task 2023-03-29T04:19:32.378Z] 04:19:32     INFO -   File "/builds/worker/workspace/build/venv/lib/python3.7/site-packages/marionette_driver/marionette.py", line 715, in _handle_error
[task 2023-03-29T04:19:32.378Z] 04:19:32     INFO -     raise errors.lookup(error)(message, stacktrace=stacktrace)
[task 2023-03-29T04:19:32.379Z] 04:19:32     INFO - TEST-INFO took 851459ms
[task 2023-03-29T04:19:32.381Z] 04:19:32    ERROR - test_end for testing/marionette/harness/marionette_harness/tests/unit/test_click.py TestClick.test_clicking_on_a_multiline_link logged while not in progress. Logged with data: {"message": "marionette_driver.errors.InvalidSessionIdException: Please start a session", "expected": "PASS", "stack": "Traceback (most recent call last):\n  File \"/builds/worker/workspace/build/venv/lib/python3.7/site-packages/marionette_harness/marionette_test/testcases.py\", line 231, in run\n    self.tearDown()\n  File \"/builds/worker/workspace/build/tests/marionette/tests/testing/marionette/harness/marionette_harness/tests/unit/test_click.py\", line 93, in tearDown\n    self.close_all_tabs()\n  File \"/builds/worker/workspace/build/venv/lib/python3.7/site-packages/marionette_harness/runner/mixins/window_manager.py\", line 31, in close_all_tabs\n    current_window_handles = self.marionette.window_handles\n  File \"/builds/worker/workspace/build/venv/lib/python3.7/site-packages/marionette_driver/marionette.py\", line 1441, in window_handles\n    with self.using_context(\"content\"):\n  File \"/usr/lib/python3.7/contextlib.py\", line 112, in __enter__\n    return next(self.gen)\n  File \"/builds/worker/workspace/build/venv/lib/python3.7/site-packages/marionette_driver/marionette.py\", line 1522, in using_context\n    scope = self._send_message(\"Marionette:GetContext\", key=\"value\")\n  File \"/builds/worker/workspace/build/venv/lib/python3.7/site-packages/marionette_driver/decorators.py\", line 24, in _\n    return func(*args, **kwargs)\n  File \"/builds/worker/workspace/build/venv/lib/python3.7/site-packages/marionette_driver/marionette.py\", line 693, in _send_message\n    raise errors.InvalidSessionIdException(\"Please start a session\")\n", "extra": {"class_name": "test_click.TestClick", "method_name": "test_clicking_on_a_multiline_link"}, "test": "testing/marionette/harness/marionette_harness/tests/unit/test_click.py TestClick.test_clicking_on_a_multiline_link", "status": "ERROR"}
[task 2023-03-29T04:19:32.382Z] 04:19:32     INFO - TEST-START | testing/marionette/harness/marionette_harness/tests/unit/test_click.py TestClick.test_container_element_outside_view

The problematic lines are:
https://treeherder.mozilla.org/logviewer?job_id=410610819&repo=mozilla-central&lineNumber=10087-10109

INFO -  1680062721108	Marionette	DEBUG	30 -> [0,2,"WebDriver:Navigate",{"url":"http://127.0.0.1:42699/clicks.html"}]
INFO -  1680062721113	Marionette	TRACE	[50] Received event beforeunload for about:blank
INFO -  1680062721126	Marionette	TRACE	Remoteness change detected. Set new top-level browsing context to 51
INFO -  DEBUG: Adding blocker ContentParent: id=7fe802f8ef00 for phase xpcom-will-shutdown
INFO -  DEBUG: Adding blocker ContentParent: id=7fe802f8ef00 for phase profile-before-change
INFO -  DEBUG: Adding blocker ContentParent: id=7fe802f8ef00 for phase quit-application-granted
INFO -  DEBUG: Adding blocker ContentParent: id=7fe802f90800 for phase xpcom-will-shutdown
INFO -  DEBUG: Adding blocker ContentParent: id=7fe802f90800 for phase profile-before-change
INFO -  DEBUG: Adding blocker ContentParent: id=7fe802f90800 for phase quit-application-granted
INFO -  DEBUG: Adding blocker ContentParent: id=7fe802f90d00 for phase xpcom-will-shutdown
INFO -  DEBUG: Adding blocker ContentParent: id=7fe802f90d00 for phase profile-before-change
INFO -  DEBUG: Adding blocker ContentParent: id=7fe802f90d00 for phase quit-application-granted
INFO -  console.error: (new Error("Polling for changes failed: Unexpected content-type \"text/plain;charset=US-ASCII\".", "resource://services-settings/remote-settings.sys.mjs", 324))
INFO -  1680062725343	addons.xpi	ERROR	System addon update list error SyntaxError: The URI is malformed.
INFO -  DEBUG: Adding blocker SessionFile: Finish writing Session Restore data for phase IOUtils: waiting for profileBeforeChange IO to complete
INFO -  DEBUG: Completed blocker SessionFile: Finish writing Session Restore data for phase IOUtils: waiting for profileBeforeChange IO to complete
INFO -  DEBUG: Adding blocker SessionFile: Finish writing Session Restore data for phase IOUtils: waiting for profileBeforeChange IO to complete
INFO -  DEBUG: Completed blocker SessionFile: Finish writing Session Restore data for phase IOUtils: waiting for profileBeforeChange IO to complete
INFO -  DEBUG: Adding blocker OS.File: flush pending requests, warn about unclosed files, shut down service. for phase xpcom-will-shutdown
INFO -  DEBUG: Adding blocker OS.File: flush I/O queued before profileBeforeChange for phase profile-before-change
INFO -  DEBUG: Adding blocker Transaction (20) for phase places.sqlite#1: waiting for clients
INFO -  DEBUG: Completed blocker Transaction (20) for phase places.sqlite#1: waiting for clients
INFO -  1680063021111	Marionette	DEBUG	30 <- [1,2,{"error":"timeout","message":"TimedPromise timed out after 300000 ms","stacktrace":"RemoteError@chrome://remote/content/shared/RemoteError.sys.mjs:8:8\nWebDriverError@chrome://remote/content/shared/webdriver/Er ... or@chrome://remote/content/shared/webdriver/Errors.sys.mjs:492:5\nbail@chrome://remote/content/marionette/sync.sys.mjs:211:19\n"},null]

We detect a remoteness change but then we may have lost the navigation events. Purely using a WebProgressListener might help here, which is covered on bug 1664165.

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit BugBot documentation.