Closed Bug 1709205 Opened 5 years ago Closed 4 years ago

Intermittent TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/execute_script/cyclic.py | expected OK

Categories

(Remote Protocol :: Marionette, defect, P5)

defect

Tracking

(Not tracked)

RESOLVED INCOMPLETE

People

(Reporter: intermittent-bug-filer, Unassigned)

References

Details

(Keywords: intermittent-failure)

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


[task 2021-05-03T20:33:59.546Z] 20:33:59     INFO - TEST-OK | /webdriver/tests/execute_script/collections.py | took 9818ms
[task 2021-05-03T20:33:59.548Z] 20:33:59     INFO - TEST-START | /webdriver/tests/execute_script/cyclic.py
[task 2021-05-03T20:33:59.641Z] 20:33:59     INFO - STDOUT: ============================= test session starts =============================
[task 2021-05-03T20:33:59.642Z] 20:33:59     INFO - STDOUT: platform win32 -- Python 3.7.3, pytest-6.1.1, py-1.5.2, pluggy-unknown -- c:\mozilla-build\python3\python.exe
[task 2021-05-03T20:33:59.644Z] 20:33:59     INFO - STDOUT: rootdir: Z:\task_1620073059\build
[task 2021-05-03T20:33:59.645Z] 20:33:59     INFO - STDOUT: plugins: asyncio-0.14.0
[task 2021-05-03T20:33:59.646Z] 20:33:59     INFO - STDOUT: collecting ... 
[task 2021-05-03T20:33:59.660Z] 20:33:59     INFO - STDOUT: collected 6 items
[task 2021-05-03T20:33:59.661Z] 20:33:59     INFO - STDOUT: tests/web-platform/tests/webdriver/tests/execute_script/cyclic.py::test_array 
[task 2021-05-03T20:33:59.663Z] 20:33:59     INFO - PID 2584 | 1620074039661	webdriver::server	DEBUG	-> POST /session/a78268f3-39d5-43ea-9a9c-1287828dc26a/window/rect {"width": 800, "height": 600}
[task 2021-05-03T20:34:01.127Z] 20:34:01     INFO - PID 2584 | 1620074041122	Marionette	DEBUG	0 -> [0,156,"WebDriver:SetWindowRect",{"height":600,"width":800}]
[task 2021-05-03T20:34:01.128Z] 20:34:01     INFO - PID 2584 | 1620074041122	Marionette	DEBUG	0 <- [1,156,null,{"x":100,"y":100,"width":800,"height":600}]
[task 2021-05-03T20:34:01.129Z] 20:34:01     INFO - PID 2584 | 1620074041125	webdriver::server	DEBUG	<- 200 OK {"value":{"x":100,"y":100,"width":800,"height":600}}
[task 2021-05-03T20:34:01.130Z] 20:34:01     INFO - PID 2584 | 1620074041127	webdriver::server	DEBUG	-> POST /session/a78268f3-39d5-43ea-9a9c-1287828dc26a/window/rect {"x": 100, "y": 100}
[task 2021-05-03T20:34:06.534Z] 20:34:06     INFO - PID 2584 | 1620074046527	Marionette	DEBUG	0 -> [0,157,"WebDriver:SetWindowRect",{"x":100,"y":100}]
[task 2021-05-03T20:34:06.535Z] 20:34:06     INFO - PID 2584 | 1620074046527	Marionette	DEBUG	0 <- [1,157,null,{"x":100,"y":100,"width":800,"height":600}]
[task 2021-05-03T20:34:06.537Z] 20:34:06     INFO - PID 2584 | 1620074046533	webdriver::server	DEBUG	<- 200 OK {"value":{"x":100,"y":100,"width":800,"height":600}}
[task 2021-05-03T20:34:06.538Z] 20:34:06     INFO - PID 2584 | 1620074046535	webdriver::server	DEBUG	-> POST /session/a78268f3-39d5-43ea-9a9c-1287828dc26a/execute/sync {"script": "\n        let arr = [];\n        arr.push(arr);\n        return arr;\n        ", "args": []}
[task 2021-05-03T20:34:06.539Z] 20:34:06     INFO - PID 2584 | 1620074046532	Marionette	DEBUG	0 -> [0,158,"WebDriver:ExecuteScript",{"args":[],"script":"\n        let arr = [];\n        arr.push(arr);\n        return arr;\n        "}]
[task 2021-05-03T20:34:06.542Z] 20:34:06     INFO - STDOUT: PASSED
[task 2021-05-03T20:34:06.543Z] 20:34:06     INFO - PID 2584 | 1620074046535	Marionette	DEBUG	0 <- [1,158,{"error":"javascript error","message":"Cyclic object value","stacktrace":"WebDriverError@chrome://marionette/content/e ... te/content/evaluate.js:301:12\nreceiveMessage@chrome://marionette/content/actors/MarionetteCommandsChild.jsm:155:31\n"},null]
[task 2021-05-03T20:34:06.545Z] 20:34:06     INFO - PID 2584 | 1620074046540	webdriver::server	DEBUG	<- 500 Internal Server Error {"value":{"error":"javascript error","message":"Cyclic object value","stacktrace":"WebDriverError@chrome://marionette/content/error.js:181:5\nJavaScriptError@chrome://marionette/content/error.js:360:5\nassert.acyclic@chrome://marionette/content/assert.js:47:11\nevaluate.toJSON@chrome://marionette/content/evaluate.js:301:12\nreceiveMessage@chrome://marionette/content/actors/MarionetteCommandsChild.jsm:155:31\n"}}
[task 2021-05-03T20:34:06.547Z] 20:34:06     INFO - PID 2584 | 1620074046541	webdriver::server	DEBUG	-> POST /session/a78268f3-39d5-43ea-9a9c-1287828dc26a/timeouts {"implicit": 0}
[task 2021-05-03T20:34:06.548Z] 20:34:06     INFO - PID 2584 | 1620074046537	Marionette	DEBUG	0 -> [0,159,"WebDriver:SetTimeouts",{"implicit":0}]
[task 2021-05-03T20:34:06.549Z] 20:34:06     INFO - PID 2584 | 1620074046537	Marionette	DEBUG	0 <- [1,159,null,{"value":null}]
[task 2021-05-03T20:34:06.550Z] 20:34:06     INFO - PID 2584 | 1620074046542	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2021-05-03T20:34:06.551Z] 20:34:06     INFO - PID 2584 | 1620074046544	webdriver::server	DEBUG	-> POST /session/a78268f3-39d5-43ea-9a9c-1287828dc26a/timeouts {"pageLoad": 300000}
[task 2021-05-03T20:34:06.552Z] 20:34:06     INFO - PID 2584 | 1620074046539	Marionette	DEBUG	0 -> [0,160,"WebDriver:SetTimeouts",{"pageLoad":300000}]
[task 2021-05-03T20:34:06.554Z] 20:34:06     INFO - PID 2584 | 1620074046540	Marionette	DEBUG	0 <- [1,160,null,{"value":null}]
[task 2021-05-03T20:34:06.555Z] 20:34:06     INFO - PID 2584 | 1620074046544	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2021-05-03T20:34:06.556Z] 20:34:06     INFO - PID 2584 | 1620074046546	webdriver::server	DEBUG	-> POST /session/a78268f3-39d5-43ea-9a9c-1287828dc26a/timeouts {"script": 30000}
[task 2021-05-03T20:34:06.558Z] 20:34:06     INFO - PID 2584 | 1620074046542	Marionette	DEBUG	0 -> [0,161,"WebDriver:SetTimeouts",{"script":30000}]
[task 2021-05-03T20:34:06.559Z] 20:34:06     INFO - PID 2584 | 1620074046542	Marionette	DEBUG	0 <- [1,161,null,{"value":null}]
[task 2021-05-03T20:34:06.560Z] 20:34:06     INFO - PID 2584 | 1620074046547	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2021-05-03T20:34:06.561Z] 20:34:06     INFO - PID 2584 | 1620074046548	webdriver::server	DEBUG	-> GET /session/a78268f3-39d5-43ea-9a9c-1287828dc26a/window
[task 2021-05-03T20:34:06.562Z] 20:34:06     INFO - PID 2584 | 1620074046544	Marionette	DEBUG	0 -> [0,162,"WebDriver:GetWindowHandle",{}]
[task 2021-05-03T20:34:06.563Z] 20:34:06     INFO - PID 2584 | 1620074046544	Marionette	DEBUG	0 <- [1,162,null,{"value":"19"}]
[task 2021-05-03T20:34:06.565Z] 20:34:06     INFO - PID 2584 | 1620074046549	webdriver::server	DEBUG	<- 200 OK {"value":"19"}
[task 2021-05-03T20:34:06.566Z] 20:34:06     INFO - PID 2584 | 1620074046550	webdriver::server	DEBUG	-> GET /session/a78268f3-39d5-43ea-9a9c-1287828dc26a/window
[task 2021-05-03T20:34:06.567Z] 20:34:06     INFO - PID 2584 | 1620074046545	Marionette	DEBUG	0 -> [0,163,"WebDriver:GetWindowHandle",{}]
[task 2021-05-03T20:34:06.569Z] 20:34:06     INFO - PID 2584 | 1620074046546	Marionette	DEBUG	0 <- [1,163,null,{"value":"19"}]
[task 2021-05-03T20:34:06.570Z] 20:34:06     INFO - PID 2584 | 1620074046550	webdriver::server	DEBUG	<- 200 OK {"value":"19"}
[task 2021-05-03T20:34:06.571Z] 20:34:06     INFO - PID 2584 | 1620074046552	webdriver::server	DEBUG	-> GET /session/a78268f3-39d5-43ea-9a9c-1287828dc26a/window/handles
[task 2021-05-03T20:34:06.572Z] 20:34:06     INFO - PID 2584 | 1620074046547	Marionette	DEBUG	0 -> [0,164,"WebDriver:GetWindowHandles",{}]
[task 2021-05-03T20:34:06.573Z] 20:34:06     INFO - PID 2584 | 1620074046548	Marionette	DEBUG	0 <- [1,164,null,["19"]]
[task 2021-05-03T20:34:06.574Z] 20:34:06     INFO - PID 2584 | 1620074046552	webdriver::server	DEBUG	<- 200 OK {"value":["19"]}
[task 2021-05-03T20:34:06.576Z] 20:34:06     INFO - PID 2584 | 1620074046554	webdriver::server	DEBUG	-> POST /session/a78268f3-39d5-43ea-9a9c-1287828dc26a/window {"handle": "19"}
[task 2021-05-03T20:34:06.577Z] 20:34:06     INFO - PID 2584 | 1620074046550	Marionette	DEBUG	0 -> [0,165,"WebDriver:SwitchToWindow",{"handle":"19","name":"19"}]
[task 2021-05-03T20:34:06.578Z] 20:34:06     INFO - PID 2584 | 1620074046550	Marionette	DEBUG	0 <- [1,165,null,{"value":null}]
[task 2021-05-03T20:34:06.579Z] 20:34:06     INFO - PID 2584 | 1620074046555	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2021-05-03T20:34:06.581Z] 20:34:06     INFO - PID 2584 | 1620074046556	webdriver::server	DEBUG	-> POST /session/a78268f3-39d5-43ea-9a9c-1287828dc26a/alert/dismiss {}
[task 2021-05-03T20:34:06.582Z] 20:34:06     INFO - PID 2584 | 1620074046552	Marionette	DEBUG	0 -> [0,166,"WebDriver:DismissAlert",{}]
[task 2021-05-03T20:34:06.584Z] 20:34:06     INFO - PID 2584 | 1620074046552	Marionette	DEBUG	0 <- [1,166,{"error":"no such alert","message":"","stacktrace":"WebDriverError@chrome://marionette/content/error.js:181:5\nNoSuchA ... t@chrome://marionette/content/server.js:238:9\n_onJSONObjectReady/<@chrome://marionette/content/transport.js:504:20\n"},null]
[task 2021-05-03T20:34:06.586Z] 20:34:06     INFO - PID 2584 | 1620074046557	webdriver::server	DEBUG	<- 404 Not Found {"value":{"error":"no such alert","message":"","stacktrace":"WebDriverError@chrome://marionette/content/error.js:181:5\nNoSuchAlertError@chrome://marionette/content/error.js:382:5\nGeckoDriver.prototype._checkIfAlertIsPresent@chrome://marionette/content/driver.js:2722:11\nGeckoDriver.prototype.dismissDialog@chrome://marionette/content/driver.js:2625:8\ndespatch@chrome://marionette/content/server.js:291:40\nexecute@chrome://marionette/content/server.js:264:16\nonPacket/<@chrome://marionette/content/server.js:237:20\nonPacket@chrome://marionette/content/server.js:238:9\n_onJSONObjectReady/<@chrome://marionette/content/transport.js:504:20\n"}}
[task 2021-05-03T20:34:06.587Z] 20:34:06     INFO - PID 2584 | 1620074046558	webdriver::server	DEBUG	-> POST /session/a78268f3-39d5-43ea-9a9c-1287828dc26a/window {"handle": "19"}
[task 2021-05-03T20:34:06.589Z] 20:34:06     INFO - PID 2584 | 1620074046554	Marionette	DEBUG	0 -> [0,167,"WebDriver:SwitchToWindow",{"handle":"19","name":"19"}]
[task 2021-05-03T20:34:06.590Z] 20:34:06     INFO - PID 2584 | 1620074046554	Marionette	DEBUG	0 <- [1,167,null,{"value":null}]
[task 2021-05-03T20:34:06.591Z] 20:34:06     INFO - PID 2584 | 1620074046559	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2021-05-03T20:34:06.592Z] 20:34:06     INFO - PID 2584 | 1620074046560	webdriver::server	DEBUG	-> GET /session/a78268f3-39d5-43ea-9a9c-1287828dc26a/window
[task 2021-05-03T20:34:06.594Z] 20:34:06     INFO - PID 2584 | 1620074046556	Marionette	DEBUG	0 -> [0,168,"WebDriver:GetWindowHandle",{}]
[task 2021-05-03T20:34:06.595Z] 20:34:06     INFO - PID 2584 | 1620074046556	Marionette	DEBUG	0 <- [1,168,null,{"value":"19"}]
[task 2021-05-03T20:34:06.596Z] 20:34:06     INFO - PID 2584 | 1620074046561	webdriver::server	DEBUG	<- 200 OK {"value":"19"}
[task 2021-05-03T20:34:06.597Z] 20:34:06     INFO - PID 2584 | 1620074046562	webdriver::server	DEBUG	-> GET /session/a78268f3-39d5-43ea-9a9c-1287828dc26a/window/handles
[task 2021-05-03T20:34:06.598Z] 20:34:06     INFO - PID 2584 | 1620074046558	Marionette	DEBUG	0 -> [0,169,"WebDriver:GetWindowHandles",{}]
[task 2021-05-03T20:34:06.600Z] 20:34:06     INFO - PID 2584 | 1620074046558	Marionette	DEBUG	0 <- [1,169,null,["19"]]
[task 2021-05-03T20:34:06.601Z] 20:34:06     INFO - PID 2584 | 1620074046563	webdriver::server	DEBUG	<- 200 OK {"value":["19"]}
[task 2021-05-03T20:34:06.602Z] 20:34:06     INFO - PID 2584 | 1620074046564	webdriver::server	DEBUG	-> POST /session/a78268f3-39d5-43ea-9a9c-1287828dc26a/window {"handle": "19"}
[task 2021-05-03T20:34:12.352Z] 20:34:12     INFO - PID 2584 | 1620074052343	Marionette	DEBUG	0 -> [0,170,"WebDriver:SwitchToWindow",{"handle":"19","name":"19"}]
[task 2021-05-03T20:34:12.353Z] 20:34:12     INFO - PID 2584 | 1620074052343	Marionette	DEBUG	0 <- [1,170,null,{"value":null}]
[task 2021-05-03T20:34:12.354Z] 20:34:12     INFO - PID 2584 | 1620074052351	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2021-05-03T20:34:12.355Z] 20:34:12     INFO - PID 2584 | 1620074052352	webdriver::server	DEBUG	-> POST /session/a78268f3-39d5-43ea-9a9c-1287828dc26a/window/rect {"width": 800, "height": 600}
[task 2021-05-03T20:34:12.364Z] 20:34:12     INFO - PID 2584 | 1620074052354	Marionette	DEBUG	0 -> [0,171,"WebDriver:SetWindowRect",{"height":600,"width":800}]
[task 2021-05-03T20:34:12.365Z] 20:34:12     INFO - PID 2584 | 1620074052354	Marionette	DEBUG	0 <- [1,171,null,{"x":100,"y":100,"width":800,"height":600}]
[task 2021-05-03T20:34:12.365Z] 20:34:12     INFO - PID 2584 | 1620074052361	webdriver::server	DEBUG	<- 200 OK {"value":{"x":100,"y":100,"width":800,"height":600}}
[task 2021-05-03T20:34:12.366Z] 20:34:12     INFO - PID 2584 | 1620074052362	webdriver::server	DEBUG	-> POST /session/a78268f3-39d5-43ea-9a9c-1287828dc26a/frame {"id": null}
[task 2021-05-03T20:34:12.369Z] 20:34:12     INFO - PID 2584 | 1620074052361	Marionette	DEBUG	0 -> [0,172,"WebDriver:SwitchToFrame",{"id":null}]
[task 2021-05-03T20:34:15.975Z] 20:34:15     INFO - PID 2584 | 1620074055966	Marionette	DEBUG	0 <- [1,172,null,{"value":null}]
[task 2021-05-03T20:34:15.981Z] 20:34:15     INFO - PID 2584 | 1620074055979	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2021-05-03T20:34:15.983Z] 20:34:15     INFO - STDOUT: tests/web-platform/tests/webdriver/tests/execute_script/cyclic.py::test_object 
[task 2021-05-03T20:34:15.984Z] 20:34:15     INFO - PID 2584 | 1620074055982	webdriver::server	DEBUG	-> POST /session/a78268f3-39d5-43ea-9a9c-1287828dc26a/window/rect {"width": 800, "height": 600}
[task 2021-05-03T20:34:21.480Z] 20:34:21     INFO - PID 2584 | 1620074061470	Marionette	DEBUG	0 -> [0,173,"WebDriver:SetWindowRect",{"height":600,"width":800}]
[task 2021-05-03T20:34:21.482Z] 20:34:21     INFO - PID 2584 | 1620074061470	Marionette	DEBUG	0 <- [1,173,null,{"x":100,"y":100,"width":800,"height":600}]
[task 2021-05-03T20:34:21.483Z] 20:34:21     INFO - PID 2584 | 1620074061479	webdriver::server	DEBUG	<- 200 OK {"value":{"x":100,"y":100,"width":800,"height":600}}
[task 2021-05-03T20:34:21.484Z] 20:34:21     INFO - PID 2584 | 1620074061481	webdriver::server	DEBUG	-> POST /session/a78268f3-39d5-43ea-9a9c-1287828dc26a/window/rect {"x": 100, "y": 100}
[task 2021-05-03T20:34:21.485Z] 20:34:21     INFO - PID 2584 | 1620074061473	Marionette	DEBUG	0 -> [0,174,"WebDriver:SetWindowRect",{"x":100,"y":100}]
[task 2021-05-03T20:34:21.487Z] 20:34:21     INFO - PID 2584 | 1620074061473	Marionette	DEBUG	0 <- [1,174,null,{"x":100,"y":100,"width":800,"height":600}]
[task 2021-05-03T20:34:21.488Z] 20:34:21     INFO - PID 2584 | 1620074061482	webdriver::server	DEBUG	<- 200 OK {"value":{"x":100,"y":100,"width":800,"height":600}}
[task 2021-05-03T20:34:21.489Z] 20:34:21     INFO - PID 2584 | 1620074061484	webdriver::server	DEBUG	-> POST /session/a78268f3-39d5-43ea-9a9c-1287828dc26a/execute/sync {"script": "\n        let obj = {};\n        obj.reference = obj;\n        return obj;\n        ", "args": []}
[task 2021-05-03T20:34:21.491Z] 20:34:21     INFO - PID 2584 | 1620074061477	Marionette	DEBUG	0 -> [0,175,"WebDriver:ExecuteScript",{"args":[],"script":"\n        let obj = {};\n        obj.reference = obj;\n        return obj;\n        "}]
[task 2021-05-03T20:34:21.492Z] 20:34:21     INFO - PID 2584 | 1620074061480	Marionette	DEBUG	0 <- [1,175,{"error":"javascript error","message":"Cyclic object value","stacktrace":"WebDriverError@chrome://marionette/content/e ... te/content/evaluate.js:337:12\nreceiveMessage@chrome://marionette/content/actors/MarionetteCommandsChild.jsm:155:31\n"},null]
[task 2021-05-03T20:34:21.493Z] 20:34:21     INFO - STDOUT: PASSED
[task 2021-05-03T20:34:21.495Z] 20:34:21     INFO - PID 2584 | 1620074061489	webdriver::server	DEBUG	<- 500 Internal Server Error {"value":{"error":"javascript error","message":"Cyclic object value","stacktrace":"WebDriverError@chrome://marionette/content/error.js:181:5\nJavaScriptError@chrome://marionette/content/error.js:360:5\nassert.acyclic@chrome://marionette/content/assert.js:47:11\nevaluate.toJSON@chrome://marionette/content/evaluate.js:337:12\nreceiveMessage@chrome://marionette/content/actors/MarionetteCommandsChild.jsm:155:31\n"}}
[task 2021-05-03T20:34:21.496Z] 20:34:21     INFO - PID 2584 | 1620074061492	webdriver::server	DEBUG	-> POST /session/a78268f3-39d5-43ea-9a9c-1287828dc26a/timeouts {"implicit": 0}
[task 2021-05-03T20:34:21.497Z] 20:34:21     INFO - PID 2584 | 1620074061487	Marionette	DEBUG	0 -> [0,176,"WebDriver:SetTimeouts",{"implicit":0}]
[task 2021-05-03T20:34:21.498Z] 20:34:21     INFO - PID 2584 | 1620074061487	Marionette	DEBUG	0 <- [1,176,null,{"value":null}]
[task 2021-05-03T20:34:21.499Z] 20:34:21     INFO - PID 2584 | 1620074061496	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2021-05-03T20:34:21.501Z] 20:34:21     INFO - PID 2584 | 1620074061498	webdriver::server	DEBUG	-> POST /session/a78268f3-39d5-43ea-9a9c-1287828dc26a/timeouts {"pageLoad": 300000}
[task 2021-05-03T20:34:21.502Z] 20:34:21     INFO - PID 2584 | 1620074061490	Marionette	DEBUG	0 -> [0,177,"WebDriver:SetTimeouts",{"pageLoad":300000}]
[task 2021-05-03T20:34:21.503Z] 20:34:21     INFO - PID 2584 | 1620074061490	Marionette	DEBUG	0 <- [1,177,null,{"value":null}]
[task 2021-05-03T20:34:21.505Z] 20:34:21     INFO - PID 2584 | 1620074061499	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2021-05-03T20:34:21.506Z] 20:34:21     INFO - PID 2584 | 1620074061500	webdriver::server	DEBUG	-> POST /session/a78268f3-39d5-43ea-9a9c-1287828dc26a/timeouts {"script": 30000}
[task 2021-05-03T20:34:21.507Z] 20:34:21     INFO - PID 2584 | 1620074061492	Marionette	DEBUG	0 -> [0,178,"WebDriver:SetTimeouts",{"script":30000}]
[task 2021-05-03T20:34:21.508Z] 20:34:21     INFO - PID 2584 | 1620074061492	Marionette	DEBUG	0 <- [1,178,null,{"value":null}]
[task 2021-05-03T20:34:21.509Z] 20:34:21     INFO - PID 2584 | 1620074061501	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2021-05-03T20:34:21.510Z] 20:34:21     INFO - PID 2584 | 1620074061502	webdriver::server	DEBUG	-> GET /session/a78268f3-39d5-43ea-9a9c-1287828dc26a/window
[task 2021-05-03T20:34:21.511Z] 20:34:21     INFO - PID 2584 | DEBUG: Adding blocker SessionFile: Finish writing Session Restore data for phase profile-before-change
[task 2021-05-03T20:34:21.513Z] 20:34:21     INFO - PID 2584 | 1620074061495	Marionette	DEBUG	0 -> [0,179,"WebDriver:GetWindowHandle",{}]
[task 2021-05-03T20:34:21.514Z] 20:34:21     INFO - PID 2584 | 1620074061495	Marionette	DEBUG	0 <- [1,179,null,{"value":"19"}]
[task 2021-05-03T20:34:21.515Z] 20:34:21     INFO - PID 2584 | 1620074061505	webdriver::server	DEBUG	<- 200 OK {"value":"19"}
[task 2021-05-03T20:34:21.516Z] 20:34:21     INFO - PID 2584 | 1620074061506	webdriver::server	DEBUG	-> GET /session/a78268f3-39d5-43ea-9a9c-1287828dc26a/window
[task 2021-05-03T20:34:23.946Z] 20:34:23     INFO - PID 2584 | DEBUG: Completed blocker SessionFile: Finish writing Session Restore data for phase profile-before-change
[task 2021-05-03T20:34:23.951Z] 20:34:23     INFO - PID 2584 | 1620074063938	Marionette	DEBUG	0 -> [0,180,"WebDriver:GetWindowHandle",{}]
[task 2021-05-03T20:34:23.953Z] 20:34:23     INFO - PID 2584 | 1620074063939	Marionette	DEBUG	0 <- [1,180,null,{"value":"19"}]
[task 2021-05-03T20:34:23.953Z] 20:34:23     INFO - PID 2584 | 1620074063950	webdriver::server	DEBUG	<- 200 OK {"value":"19"}
[task 2021-05-03T20:34:23.954Z] 20:34:23     INFO - PID 2584 | 1620074063952	webdriver::server	DEBUG	-> GET /session/a78268f3-39d5-43ea-9a9c-1287828dc26a/window/handles
[task 2021-05-03T20:34:24.767Z] 20:34:24     INFO - PID 2584 | 1620074064755	Marionette	DEBUG	0 -> [0,181,"WebDriver:GetWindowHandles",{}]
[task 2021-05-03T20:34:24.768Z] 20:34:24     INFO - PID 2584 | 1620074064755	Marionette	DEBUG	0 <- [1,181,null,["19"]]
[task 2021-05-03T20:34:24.769Z] 20:34:24     INFO - PID 2584 | 1620074064766	webdriver::server	DEBUG	<- 200 OK {"value":["19"]}
[task 2021-05-03T20:34:24.771Z] 20:34:24     INFO - PID 2584 | 1620074064768	webdriver::server	DEBUG	-> POST /session/a78268f3-39d5-43ea-9a9c-1287828dc26a/window {"handle": "19"}
[task 2021-05-03T20:34:24.841Z] 20:34:24     INFO - PID 2584 | 1620074064829	Marionette	DEBUG	0 -> [0,182,"WebDriver:SwitchToWindow",{"handle":"19","name":"19"}]
[task 2021-05-03T20:34:24.841Z] 20:34:24     INFO - PID 2584 | 1620074064829	Marionette	DEBUG	0 <- [1,182,null,{"value":null}]
[task 2021-05-03T20:34:24.843Z] 20:34:24     INFO - PID 2584 | 1620074064839	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2021-05-03T20:34:24.844Z] 20:34:24     INFO - PID 2584 | 1620074064841	webdriver::server	DEBUG	-> POST /session/a78268f3-39d5-43ea-9a9c-1287828dc26a/alert/dismiss {}
[task 2021-05-03T20:34:24.847Z] 20:34:24     INFO - PID 2584 | 1620074064836	Marionette	DEBUG	0 -> [0,183,"WebDriver:DismissAlert",{}]
[task 2021-05-03T20:34:24.849Z] 20:34:24     INFO - PID 2584 | 1620074064837	Marionette	DEBUG	0 <- [1,183,{"error":"no such alert","message":"","stacktrace":"WebDriverError@chrome://marionette/content/error.js:181:5\nNoSuchA ... t@chrome://marionette/content/server.js:238:9\n_onJSONObjectReady/<@chrome://marionette/content/transport.js:504:20\n"},null]
[task 2021-05-03T20:34:24.851Z] 20:34:24     INFO - PID 2584 | 1620074064847	webdriver::server	DEBUG	<- 404 Not Found {"value":{"error":"no such alert","message":"","stacktrace":"WebDriverError@chrome://marionette/content/error.js:181:5\nNoSuchAlertError@chrome://marionette/content/error.js:382:5\nGeckoDriver.prototype._checkIfAlertIsPresent@chrome://marionette/content/driver.js:2722:11\nGeckoDriver.prototype.dismissDialog@chrome://marionette/content/driver.js:2625:8\ndespatch@chrome://marionette/content/server.js:291:40\nexecute@chrome://marionette/content/server.js:264:16\nonPacket/<@chrome://marionette/content/server.js:237:20\nonPacket@chrome://marionette/content/server.js:238:9\n_onJSONObjectReady/<@chrome://marionette/content/transport.js:504:20\n"}}
[task 2021-05-03T20:34:24.852Z] 20:34:24     INFO - PID 2584 | 1620074064848	webdriver::server	DEBUG	-> POST /session/a78268f3-39d5-43ea-9a9c-1287828dc26a/window {"handle": "19"}
[task 2021-05-03T20:34:24.854Z] 20:34:24     INFO - PID 2584 | 1620074064839	Marionette	DEBUG	0 -> [0,184,"WebDriver:SwitchToWindow",{"handle":"19","name":"19"}]
[task 2021-05-03T20:34:24.855Z] 20:34:24     INFO - PID 2584 | 1620074064839	Marionette	DEBUG	0 <- [1,184,null,{"value":null}]
[task 2021-05-03T20:34:24.856Z] 20:34:24     INFO - PID 2584 | 1620074064849	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2021-05-03T20:34:24.857Z] 20:34:24     INFO - PID 2584 | 1620074064851	webdriver::server	DEBUG	-> GET /session/a78268f3-39d5-43ea-9a9c-1287828dc26a/window
[task 2021-05-03T20:34:24.863Z] 20:34:24     INFO - PID 2584 | 1620074064852	Marionette	DEBUG	0 -> [0,185,"WebDriver:GetWindowHandle",{}]
[task 2021-05-03T20:34:24.865Z] 20:34:24     INFO - PID 2584 | 1620074064852	Marionette	DEBUG	0 <- [1,185,null,{"value":"19"}]
[task 2021-05-03T20:34:24.866Z] 20:34:24     INFO - PID 2584 | 1620074064862	webdriver::server	DEBUG	<- 200 OK {"value":"19"}
[task 2021-05-03T20:34:24.867Z] 20:34:24     INFO - PID 2584 | 1620074064864	webdriver::server	DEBUG	-> GET /session/a78268f3-39d5-43ea-9a9c-1287828dc26a/window/handles
[task 2021-05-03T20:34:24.874Z] 20:34:24     INFO - PID 2584 | 1620074064862	Marionette	DEBUG	0 -> [0,186,"WebDriver:GetWindowHandles",{}]
[task 2021-05-03T20:34:24.875Z] 20:34:24     INFO - PID 2584 | 1620074064863	Marionette	DEBUG	0 <- [1,186,null,["19"]]
[task 2021-05-03T20:34:24.876Z] 20:34:24     INFO - PID 2584 | 1620074064873	webdriver::server	DEBUG	<- 200 OK {"value":["19"]}
[task 2021-05-03T20:34:24.877Z] 20:34:24     INFO - PID 2584 | 1620074064873	webdriver::server	DEBUG	-> POST /session/a78268f3-39d5-43ea-9a9c-1287828dc26a/window {"handle": "19"}
[task 2021-05-03T20:34:24.883Z] 20:34:24     INFO - PID 2584 | 1620074064871	Marionette	DEBUG	0 -> [0,187,"WebDriver:SwitchToWindow",{"handle":"19","name":"19"}]
[task 2021-05-03T20:34:24.883Z] 20:34:24     INFO - PID 2584 | 1620074064872	Marionette	DEBUG	0 <- [1,187,null,{"value":null}]
[task 2021-05-03T20:34:24.885Z] 20:34:24     INFO - PID 2584 | 1620074064881	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2021-05-03T20:34:24.886Z] 20:34:24     INFO - PID 2584 | 1620074064883	webdriver::server	DEBUG	-> POST /session/a78268f3-39d5-43ea-9a9c-1287828dc26a/window/rect {"width": 800, "height": 600}
[task 2021-05-03T20:34:24.888Z] 20:34:24     INFO - PID 2584 | 1620074064877	Marionette	DEBUG	0 -> [0,188,"WebDriver:SetWindowRect",{"height":600,"width":800}]
[task 2021-05-03T20:34:24.889Z] 20:34:24     INFO - PID 2584 | 1620074064877	Marionette	DEBUG	0 <- [1,188,null,{"x":100,"y":100,"width":800,"height":600}]
[task 2021-05-03T20:34:24.891Z] 20:34:24     INFO - PID 2584 | 1620074064887	webdriver::server	DEBUG	<- 200 OK {"value":{"x":100,"y":100,"width":800,"height":600}}
[task 2021-05-03T20:34:24.892Z] 20:34:24     INFO - PID 2584 | 1620074064888	webdriver::server	DEBUG	-> POST /session/a78268f3-39d5-43ea-9a9c-1287828dc26a/frame {"id": null}
[task 2021-05-03T20:34:26.704Z] 20:34:26     INFO - PID 2584 | 1620074066691	Marionette	DEBUG	0 -> [0,189,"WebDriver:SwitchToFrame",{"id":null}]
[task 2021-05-03T20:34:27.570Z] 20:34:27     INFO - PID 2584 | 1620074067558	Marionette	DEBUG	0 <- [1,189,null,{"value":null}]
[task 2021-05-03T20:34:27.574Z] 20:34:27     INFO - PID 2584 | 1620074067571	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2021-05-03T20:34:27.575Z] 20:34:27     INFO - STDOUT: tests/web-platform/tests/webdriver/tests/execute_script/cyclic.py::test_array_in_object 
[task 2021-05-03T20:34:27.576Z] 20:34:27     INFO - PID 2584 | 1620074067574	webdriver::server	DEBUG	-> POST /session/a78268f3-39d5-43ea-9a9c-1287828dc26a/window/rect {"width": 800, "height": 600}
[task 2021-05-03T20:34:27.582Z] 20:34:27     INFO - PID 2584 | 1620074067570	Marionette	DEBUG	0 -> [0,190,"WebDriver:SetWindowRect",{"height":600,"width":800}]
[task 2021-05-03T20:34:27.583Z] 20:34:27     INFO - PID 2584 | 1620074067570	Marionette	DEBUG	0 <- [1,190,null,{"x":100,"y":100,"width":800,"height":600}]
[task 2021-05-03T20:34:27.584Z] 20:34:27     INFO - PID 2584 | 1620074067581	webdriver::server	DEBUG	<- 200 OK {"value":{"x":100,"y":100,"width":800,"height":600}}
[task 2021-05-03T20:34:27.586Z] 20:34:27     INFO - PID 2584 | 1620074067582	webdriver::server	DEBUG	-> POST /session/a78268f3-39d5-43ea-9a9c-1287828dc26a/window/rect {"x": 100, "y": 100}
[task 2021-05-03T20:34:29.395Z] 20:34:29     INFO - PID 2584 | 1620074069382	Marionette	DEBUG	0 -> [0,191,"WebDriver:SetWindowRect",{"x":100,"y":100}]
[task 2021-05-03T20:34:29.396Z] 20:34:29     INFO - PID 2584 | 1620074069382	Marionette	DEBUG	0 <- [1,191,null,{"x":100,"y":100,"width":800,"height":600}]
[task 2021-05-03T20:34:29.398Z] 20:34:29     INFO - PID 2584 | 1620074069394	webdriver::server	DEBUG	<- 200 OK {"value":{"x":100,"y":100,"width":800,"height":600}}
[task 2021-05-03T20:34:29.399Z] 20:34:29     INFO - PID 2584 | 1620074069396	webdriver::server	DEBUG	-> POST /session/a78268f3-39d5-43ea-9a9c-1287828dc26a/execute/sync {"script": "\n        let arr = [];\n        arr.push(arr);\n        return {'arrayValue': arr};\n        ", "args": []}
[task 2021-05-03T20:34:29.403Z] 20:34:29     INFO - PID 2584 | 1620074069389	Marionette	DEBUG	0 -> [0,192,"WebDriver:ExecuteScript",{"args":[],"script":"\n        let arr = [];\n        arr.push(arr);\n        return {'arrayValue': arr};\n        "}]
[task 2021-05-03T20:34:29.407Z] 20:34:29     INFO - STDOUT: PASSED
[task 2021-05-03T20:34:29.409Z] 20:34:29     INFO - PID 2584 | 1620074069392	Marionette	DEBUG	0 <- [1,192,{"error":"javascript error","message":"Cyclic object value","stacktrace":"WebDriverError@chrome://marionette/content/e ... te/content/evaluate.js:337:12\nreceiveMessage@chrome://marionette/content/actors/MarionetteCommandsChild.jsm:155:31\n"},null]
[task 2021-05-03T20:34:29.410Z] 20:34:29     INFO - PID 2584 | 1620074069404	webdriver::server	DEBUG	<- 500 Internal Server Error {"value":{"error":"javascript error","message":"Cyclic object value","stacktrace":"WebDriverError@chrome://marionette/content/error.js:181:5\nJavaScriptError@chrome://marionette/content/error.js:360:5\nassert.acyclic@chrome://marionette/content/assert.js:47:11\nevaluate.toJSON@chrome://marionette/content/evaluate.js:337:12\nreceiveMessage@chrome://marionette/content/actors/MarionetteCommandsChild.jsm:155:31\n"}}
[task 2021-05-03T20:34:29.411Z] 20:34:29     INFO - PID 2584 | 1620074069405	webdriver::server	DEBUG	-> POST /session/a78268f3-39d5-43ea-9a9c-1287828dc26a/timeouts {"implicit": 0}
[task 2021-05-03T20:34:29.412Z] 20:34:29     INFO - PID 2584 | 1620074069394	Marionette	DEBUG	0 -> [0,193,"WebDriver:SetTimeouts",{"implicit":0}]
[task 2021-05-03T20:34:29.413Z] 20:34:29     INFO - PID 2584 | 1620074069394	Marionette	DEBUG	0 <- [1,193,null,{"value":null}]
[task 2021-05-03T20:34:29.415Z] 20:34:29     INFO - PID 2584 | 1620074069406	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2021-05-03T20:34:29.416Z] 20:34:29     INFO - PID 2584 | 1620074069407	webdriver::server	DEBUG	-> POST /session/a78268f3-39d5-43ea-9a9c-1287828dc26a/timeouts {"pageLoad": 300000}
[task 2021-05-03T20:34:29.417Z] 20:34:29     INFO - PID 2584 | 1620074069396	Marionette	DEBUG	0 -> [0,194,"WebDriver:SetTimeouts",{"pageLoad":300000}]
[task 2021-05-03T20:34:29.419Z] 20:34:29     INFO - PID 2584 | 1620074069397	Marionette	DEBUG	0 <- [1,194,null,{"value":null}]
[task 2021-05-03T20:34:29.420Z] 20:34:29     INFO - PID 2584 | 1620074069409	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2021-05-03T20:34:29.421Z] 20:34:29     INFO - PID 2584 | 1620074069410	webdriver::server	DEBUG	-> POST /session/a78268f3-39d5-43ea-9a9c-1287828dc26a/timeouts {"script": 30000}
[task 2021-05-03T20:34:29.423Z] 20:34:29     INFO - PID 2584 | 1620074069399	Marionette	DEBUG	0 -> [0,195,"WebDriver:SetTimeouts",{"script":30000}]
[task 2021-05-03T20:34:29.424Z] 20:34:29     INFO - PID 2584 | 1620074069399	Marionette	DEBUG	0 <- [1,195,null,{"value":null}]
[task 2021-05-03T20:34:29.425Z] 20:34:29     INFO - PID 2584 | 1620074069411	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2021-05-03T20:34:29.426Z] 20:34:29     INFO - PID 2584 | 1620074069412	webdriver::server	DEBUG	-> GET /session/a78268f3-39d5-43ea-9a9c-1287828dc26a/window
[task 2021-05-03T20:34:29.428Z] 20:34:29     INFO - PID 2584 | 1620074069401	Marionette	DEBUG	0 -> [0,196,"WebDriver:GetWindowHandle",{}]
[task 2021-05-03T20:34:29.429Z] 20:34:29     INFO - PID 2584 | 1620074069401	Marionette	DEBUG	0 <- [1,196,null,{"value":"19"}]
[task 2021-05-03T20:34:29.430Z] 20:34:29     INFO - PID 2584 | 1620074069413	webdriver::server	DEBUG	<- 200 OK {"value":"19"}
[task 2021-05-03T20:34:29.432Z] 20:34:29     INFO - PID 2584 | 1620074069414	webdriver::server	DEBUG	-> GET /session/a78268f3-39d5-43ea-9a9c-1287828dc26a/window
[task 2021-05-03T20:34:29.433Z] 20:34:29     INFO - PID 2584 | 1620074069403	Marionette	DEBUG	0 -> [0,197,"WebDriver:GetWindowHandle",{}]
[task 2021-05-03T20:34:29.435Z] 20:34:29     INFO - PID 2584 | 1620074069403	Marionette	DEBUG	0 <- [1,197,null,{"value":"19"}]
[task 2021-05-03T20:34:29.436Z] 20:34:29     INFO - PID 2584 | 1620074069415	webdriver::server	DEBUG	<- 200 OK {"value":"19"}
[task 2021-05-03T20:34:29.437Z] 20:34:29     INFO - PID 2584 | 1620074069416	webdriver::server	DEBUG	-> GET /session/a78268f3-39d5-43ea-9a9c-1287828dc26a/window/handles
[task 2021-05-03T20:34:29.438Z] 20:34:29     INFO - PID 2584 | 1620074069405	Marionette	DEBUG	0 -> [0,198,"WebDriver:GetWindowHandles",{}]
[task 2021-05-03T20:34:29.440Z] 20:34:29     INFO - PID 2584 | 1620074069405	Marionette	DEBUG	0 <- [1,198,null,["19"]]
[task 2021-05-03T20:34:29.441Z] 20:34:29     INFO - PID 2584 | 1620074069417	webdriver::server	DEBUG	<- 200 OK {"value":["19"]}
[task 2021-05-03T20:34:29.442Z] 20:34:29     INFO - PID 2584 | 1620074069418	webdriver::server	DEBUG	-> POST /session/a78268f3-39d5-43ea-9a9c-1287828dc26a/window {"handle": "19"}
[task 2021-05-03T20:34:29.444Z] 20:34:29     INFO - PID 2584 | 1620074069407	Marionette	DEBUG	0 -> [0,199,"WebDriver:SwitchToWindow",{"handle":"19","name":"19"}]
[task 2021-05-03T20:34:29.445Z] 20:34:29     INFO - PID 2584 | 1620074069407	Marionette	DEBUG	0 <- [1,199,null,{"value":null}]
[task 2021-05-03T20:34:29.446Z] 20:34:29     INFO - PID 2584 | 1620074069419	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2021-05-03T20:34:29.448Z] 20:34:29     INFO - PID 2584 | 1620074069420	webdriver::server	DEBUG	-> POST /session/a78268f3-39d5-43ea-9a9c-1287828dc26a/alert/dismiss {}
[task 2021-05-03T20:34:29.449Z] 20:34:29     INFO - PID 2584 | 1620074069409	Marionette	DEBUG	0 -> [0,200,"WebDriver:DismissAlert",{}]
[task 2021-05-03T20:34:29.451Z] 20:34:29     INFO - PID 2584 | 1620074069410	Marionette	DEBUG	0 <- [1,200,{"error":"no such alert","message":"","stacktrace":"WebDriverError@chrome://marionette/content/error.js:181:5\nNoSuchA ... t@chrome://marionette/content/server.js:238:9\n_onJSONObjectReady/<@chrome://marionette/content/transport.js:504:20\n"},null]
[task 2021-05-03T20:34:29.453Z] 20:34:29     INFO - PID 2584 | 1620074069422	webdriver::server	DEBUG	<- 404 Not Found {"value":{"error":"no such alert","message":"","stacktrace":"WebDriverError@chrome://marionette/content/error.js:181:5\nNoSuchAlertError@chrome://marionette/content/error.js:382:5\nGeckoDriver.prototype._checkIfAlertIsPresent@chrome://marionette/content/driver.js:2722:11\nGeckoDriver.prototype.dismissDialog@chrome://marionette/content/driver.js:2625:8\ndespatch@chrome://marionette/content/server.js:291:40\nexecute@chrome://marionette/content/server.js:264:16\nonPacket/<@chrome://marionette/content/server.js:237:20\nonPacket@chrome://marionette/content/server.js:238:9\n_onJSONObjectReady/<@chrome://marionette/content/transport.js:504:20\n"}}
[task 2021-05-03T20:34:29.454Z] 20:34:29     INFO - PID 2584 | 1620074069423	webdriver::server	DEBUG	-> POST /session/a78268f3-39d5-43ea-9a9c-1287828dc26a/window {"handle": "19"}
[task 2021-05-03T20:34:29.456Z] 20:34:29     INFO - PID 2584 | 1620074069412	Marionette	DEBUG	0 -> [0,201,"WebDriver:SwitchToWindow",{"handle":"19","name":"19"}]
[task 2021-05-03T20:34:29.457Z] 20:34:29     INFO - PID 2584 | 1620074069412	Marionette	DEBUG	0 <- [1,201,null,{"value":null}]
[task 2021-05-03T20:34:29.458Z] 20:34:29     INFO - PID 2584 | 1620074069424	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2021-05-03T20:34:29.459Z] 20:34:29     INFO - PID 2584 | 1620074069425	webdriver::server	DEBUG	-> GET /session/a78268f3-39d5-43ea-9a9c-1287828dc26a/window
[task 2021-05-03T20:34:29.461Z] 20:34:29     INFO - PID 2584 | 1620074069414	Marionette	DEBUG	0 -> [0,202,"WebDriver:GetWindowHandle",{}]
[task 2021-05-03T20:34:29.462Z] 20:34:29     INFO - PID 2584 | 1620074069414	Marionette	DEBUG	0 <- [1,202,null,{"value":"19"}]
[task 2021-05-03T20:34:29.463Z] 20:34:29     INFO - PID 2584 | 1620074069426	webdriver::server	DEBUG	<- 200 OK {"value":"19"}
[task 2021-05-03T20:34:29.465Z] 20:34:29     INFO - PID 2584 | 1620074069427	webdriver::server	DEBUG	-> GET /session/a78268f3-39d5-43ea-9a9c-1287828dc26a/window/handles
[task 2021-05-03T20:34:29.466Z] 20:34:29     INFO - PID 2584 | 1620074069416	Marionette	DEBUG	0 -> [0,203,"WebDriver:GetWindowHandles",{}]
[task 2021-05-03T20:34:29.467Z] 20:34:29     INFO - PID 2584 | 1620074069416	Marionette	DEBUG	0 <- [1,203,null,["19"]]
[task 2021-05-03T20:34:29.468Z] 20:34:29     INFO - PID 2584 | 1620074069428	webdriver::server	DEBUG	<- 200 OK {"value":["19"]}
[task 2021-05-03T20:34:29.470Z] 20:34:29     INFO - PID 2584 | 1620074069430	webdriver::server	DEBUG	-> POST /session/a78268f3-39d5-43ea-9a9c-1287828dc26a/window {"handle": "19"}
[task 2021-05-03T20:34:29.471Z] 20:34:29     INFO - PID 2584 | 1620074069419	Marionette	DEBUG	0 -> [0,204,"WebDriver:SwitchToWindow",{"handle":"19","name":"19"}]
[task 2021-05-03T20:34:29.472Z] 20:34:29     INFO - PID 2584 | 1620074069419	Marionette	DEBUG	0 <- [1,204,null,{"value":null}]
[task 2021-05-03T20:34:29.473Z] 20:34:29     INFO - PID 2584 | 1620074069431	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2021-05-03T20:34:29.475Z] 20:34:29     INFO - PID 2584 | 1620074069432	webdriver::server	DEBUG	-> POST /session/a78268f3-39d5-43ea-9a9c-1287828dc26a/window/rect {"width": 800, "height": 600}
[task 2021-05-03T20:34:29.476Z] 20:34:29     INFO - PID 2584 | 1620074069421	Marionette	DEBUG	0 -> [0,205,"WebDriver:SetWindowRect",{"height":600,"width":800}]
[task 2021-05-03T20:34:29.477Z] 20:34:29     INFO - PID 2584 | 1620074069422	Marionette	DEBUG	0 <- [1,205,null,{"x":100,"y":100,"width":800,"height":600}]
[task 2021-05-03T20:34:29.479Z] 20:34:29     INFO - PID 2584 | 1620074069434	webdriver::server	DEBUG	<- 200 OK {"value":{"x":100,"y":100,"width":800,"height":600}}
[task 2021-05-03T20:34:29.480Z] 20:34:29     INFO - PID 2584 | 1620074069435	webdriver::server	DEBUG	-> POST /session/a78268f3-39d5-43ea-9a9c-1287828dc26a/frame {"id": null}
[task 2021-05-03T20:34:29.481Z] 20:34:29     INFO - STDOUT: tests/web-platform/tests/webdriver/tests/execute_script/cyclic.py::test_object_in_array 
[task 2021-05-03T20:34:29.482Z] 20:34:29     INFO - PID 2584 | 1620074069424	Marionette	DEBUG	0 -> [0,206,"WebDriver:SwitchToFrame",{"id":null}]
[task 2021-05-03T20:34:29.484Z] 20:34:29     INFO - PID 2584 | 1620074069425	Marionette	DEBUG	0 <- [1,206,null,{"value":null}]
[task 2021-05-03T20:34:29.485Z] 20:34:29     INFO - PID 2584 | 1620074069437	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2021-05-03T20:34:29.486Z] 20:34:29     INFO - PID 2584 | 1620074069440	webdriver::server	DEBUG	-> POST /session/a78268f3-39d5-43ea-9a9c-1287828dc26a/window/rect {"width": 800, "height": 600}
[task 2021-05-03T20:34:29.561Z] 20:34:29     INFO - TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/execute_script/cyclic.py | expected OK
[task 2021-05-03T20:34:29.561Z] 20:34:29     INFO - TEST-INFO took 30019ms
[task 2021-05-03T20:34:29.875Z] 20:34:29     INFO - PID 2584 | 1620074069547	Marionette	DEBUG	0 -> [0,207,"WebDriver:SetWindowRect",{"height":600,"width":800}]
[task 2021-05-03T20:34:29.875Z] 20:34:29     INFO - PID 2584 | Exiting due to channel error.
[task 2021-05-03T20:34:29.876Z] 20:34:29     INFO - Closing logging queue
[task 2021-05-03T20:34:29.877Z] 20:34:29     INFO - queue closed
[task 2021-05-03T20:34:29.879Z] 20:34:29     INFO - Starting runner
[task 2021-05-03T20:34:30.555Z] 20:34:30     INFO - PID 1100 | 1620074070553	geckodriver	INFO	Listening on 127.0.0.1:54317
[task 2021-05-03T20:34:31.046Z] 20:34:31     INFO - WebDriver HTTP server listening at http://127.0.0.1:54317/
[task 2021-05-03T20:34:31.048Z] 20:34:31     INFO - TEST-START | /webdriver/tests/execute_script/execute.py```

In some cases there are 6s delays between geckodriver receiving a command and when Marionette gets it. I filed 1709264 to get this investigated.

Status: NEW → RESOLVED
Closed: 5 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 5 years ago4 years ago
Resolution: --- → INCOMPLETE
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.