Closed Bug 1757607 Opened 3 years ago Closed 3 years ago

Intermittent [tier2] TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/execute_async_script/execute_async.py | expected OK

Categories

(Remote Protocol :: Marionette, defect, P5)

defect

Tracking

(Not tracked)

RESOLVED DUPLICATE of bug 1757561

People

(Reporter: intermittent-bug-filer, Unassigned)

References

Details

(Keywords: intermittent-failure)

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


[task 2022-03-01T15:28:50.685Z] 15:28:50     INFO - STDOUT: PASSED
[task 2022-03-01T15:28:50.685Z] 15:28:50     INFO - PID 1884 | 1646148530673	Marionette	DEBUG	0 -> [0,55,"WebDriver:ExecuteAsyncScript",{"args":[],"script":"argument[0](1);"}]
[task 2022-03-01T15:28:50.685Z] 15:28:50     INFO - PID 1884 | 1646148530675	Marionette	DEBUG	0 <- [1,55,{"error":"no such window","message":"Browsing context has been discarded","stacktrace":"WebDriverError@chrome://remote/ ... ote/content/marionette/server.js:253:9\n_onJSONObjectReady/<@chrome://remote/content/marionette/transport.js:500:20\n"},null]
[task 2022-03-01T15:28:50.686Z] 15:28:50     INFO - PID 1884 | 1646148530676	webdriver::server	DEBUG	<- 404 Not Found {"value":{"error":"no such window","message":"Browsing context has been discarded","stacktrace":"WebDriverError@chrome://remote/content/shared/webdriver/Errors.jsm:183:5\nNoSuchWindowError@chrome://remote/content/shared/webdriver/Errors.jsm:437:5\nassert.that/<@chrome://remote/content/shared/webdriver/Assert.jsm:435:13\nassert.open@chrome://remote/content/shared/webdriver/Assert.jsm:143:4\nGeckoDriver.prototype.execute_@chrome://remote/content/marionette/driver.js:722:10\nGeckoDriver.prototype.executeAsyncScript@chrome://remote/content/marionette/driver.js:708:30\ndespatch@chrome://remote/content/marionette/server.js:306:40\nexecute@chrome://remote/content/marionette/server.js:279:16\nonPacket/<@chrome://remote/content/marionette/server.js:252:20\nonPacket@chrome://remote/content/marionette/server.js:253:9\n_onJSONObjectReady/<@chrome://remote/content/marionette/transport.js:500:20\n"}}
[task 2022-03-01T15:28:50.686Z] 15:28:50     INFO - PID 1884 | 1646148530681	webdriver::server	DEBUG	-> DELETE /session/c415b86e-8ce2-40c6-b124-00ccaa988469/window
[task 2022-03-01T15:28:50.687Z] 15:28:50     INFO - PID 1884 | 1646148530686	Marionette	DEBUG	0 -> [0,56,"WebDriver:CloseWindow",{}]
[task 2022-03-01T15:28:50.700Z] 15:28:50     INFO - PID 1884 | 1646148530699	Marionette	TRACE	Received DOM event TabClose for [object XULElement]
[task 2022-03-01T15:28:50.725Z] 15:28:50     INFO - PID 1884 | 1646148530724	Marionette	TRACE	Received observer notification message-manager-disconnect
[task 2022-03-01T15:28:50.726Z] 15:28:50     INFO - PID 1884 | 1646148530724	Marionette	DEBUG	0 <- [1,56,null,["97f39bb2-f3f8-43bf-b093-60002209c73d"]]
[task 2022-03-01T15:28:50.728Z] 15:28:50     INFO - PID 1884 | 1646148530727	webdriver::server	DEBUG	<- 200 OK {"value":["97f39bb2-f3f8-43bf-b093-60002209c73d"]}
[task 2022-03-01T15:28:50.729Z] 15:28:50     INFO - PID 1884 | 1646148530728	webdriver::server	DEBUG	-> GET /session/c415b86e-8ce2-40c6-b124-00ccaa988469/window/handles
[task 2022-03-01T15:28:50.729Z] 15:28:50     INFO - PID 1884 | 1646148530728	Marionette	DEBUG	0 -> [0,57,"WebDriver:GetWindowHandles",{}]
[task 2022-03-01T15:28:50.731Z] 15:28:50     INFO - PID 1884 | 1646148530729	Marionette	DEBUG	0 <- [1,57,null,["97f39bb2-f3f8-43bf-b093-60002209c73d"]]
[task 2022-03-01T15:28:50.731Z] 15:28:50     INFO - PID 1884 | 1646148530730	webdriver::server	DEBUG	<- 200 OK {"value":["97f39bb2-f3f8-43bf-b093-60002209c73d"]}
[task 2022-03-01T15:28:50.732Z] 15:28:50     INFO - PID 1884 | 1646148530730	webdriver::server	DEBUG	-> POST /session/c415b86e-8ce2-40c6-b124-00ccaa988469/window {"handle": "97f39bb2-f3f8-43bf-b093-60002209c73d"}
[task 2022-03-01T15:28:50.732Z] 15:28:50     INFO - PID 1884 | 1646148530731	Marionette	DEBUG	0 -> [0,58,"WebDriver:SwitchToWindow",{"handle":"97f39bb2-f3f8-43bf-b093-60002209c73d"}]
[task 2022-03-01T15:28:50.733Z] 15:28:50     INFO - PID 1884 | 1646148530733	Marionette	DEBUG	0 <- [1,58,null,{"value":null}]
[task 2022-03-01T15:28:50.734Z] 15:28:50     INFO - PID 1884 | 1646148530733	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2022-03-01T15:28:50.735Z] 15:28:50     INFO - PID 1884 | 1646148530734	webdriver::server	DEBUG	-> POST /session/c415b86e-8ce2-40c6-b124-00ccaa988469/timeouts {"implicit": 0}
[task 2022-03-01T15:28:50.735Z] 15:28:50     INFO - PID 1884 | 1646148530735	Marionette	DEBUG	0 -> [0,59,"WebDriver:SetTimeouts",{"implicit":0}]
[task 2022-03-01T15:28:50.737Z] 15:28:50     INFO - PID 1884 | 1646148530735	Marionette	DEBUG	0 <- [1,59,null,{"value":null}]
[task 2022-03-01T15:28:50.739Z] 15:28:50     INFO - PID 1884 | 1646148530736	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2022-03-01T15:28:50.739Z] 15:28:50     INFO - PID 1884 | 1646148530736	webdriver::server	DEBUG	-> POST /session/c415b86e-8ce2-40c6-b124-00ccaa988469/timeouts {"pageLoad": 300000}
[task 2022-03-01T15:28:50.740Z] 15:28:50     INFO - PID 1884 | 1646148530737	Marionette	DEBUG	0 -> [0,60,"WebDriver:SetTimeouts",{"pageLoad":300000}]
[task 2022-03-01T15:28:50.740Z] 15:28:50     INFO - PID 1884 | 1646148530738	Marionette	DEBUG	0 <- [1,60,null,{"value":null}]
[task 2022-03-01T15:28:50.741Z] 15:28:50     INFO - PID 1884 | 1646148530738	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2022-03-01T15:28:50.742Z] 15:28:50     INFO - PID 1884 | 1646148530739	webdriver::server	DEBUG	-> POST /session/c415b86e-8ce2-40c6-b124-00ccaa988469/timeouts {"script": 30000}
[task 2022-03-01T15:28:50.742Z] 15:28:50     INFO - PID 1884 | 1646148530740	Marionette	DEBUG	0 -> [0,61,"WebDriver:SetTimeouts",{"script":30000}]
[task 2022-03-01T15:28:50.743Z] 15:28:50     INFO - PID 1884 | 1646148530740	Marionette	DEBUG	0 <- [1,61,null,{"value":null}]
[task 2022-03-01T15:28:50.743Z] 15:28:50     INFO - PID 1884 | 1646148530741	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2022-03-01T15:28:50.745Z] 15:28:50     INFO - PID 1884 | 1646148530741	webdriver::server	DEBUG	-> GET /session/c415b86e-8ce2-40c6-b124-00ccaa988469/window
[task 2022-03-01T15:28:50.745Z] 15:28:50     INFO - PID 1884 | 1646148530742	Marionette	DEBUG	0 -> [0,62,"WebDriver:GetWindowHandle",{}]
[task 2022-03-01T15:28:50.745Z] 15:28:50     INFO - PID 1884 | 1646148530743	Marionette	DEBUG	0 <- [1,62,null,{"value":"97f39bb2-f3f8-43bf-b093-60002209c73d"}]
[task 2022-03-01T15:28:50.746Z] 15:28:50     INFO - PID 1884 | 1646148530743	webdriver::server	DEBUG	<- 200 OK {"value":"97f39bb2-f3f8-43bf-b093-60002209c73d"}
[task 2022-03-01T15:28:50.746Z] 15:28:50     INFO - PID 1884 | 1646148530744	webdriver::server	DEBUG	-> GET /session/c415b86e-8ce2-40c6-b124-00ccaa988469/window
[task 2022-03-01T15:28:50.747Z] 15:28:50     INFO - PID 1884 | 1646148530744	Marionette	DEBUG	0 -> [0,63,"WebDriver:GetWindowHandle",{}]
[task 2022-03-01T15:28:50.747Z] 15:28:50     INFO - PID 1884 | 1646148530745	Marionette	DEBUG	0 <- [1,63,null,{"value":"97f39bb2-f3f8-43bf-b093-60002209c73d"}]
[task 2022-03-01T15:28:50.748Z] 15:28:50     INFO - PID 1884 | 1646148530745	webdriver::server	DEBUG	<- 200 OK {"value":"97f39bb2-f3f8-43bf-b093-60002209c73d"}
[task 2022-03-01T15:28:50.749Z] 15:28:50     INFO - PID 1884 | 1646148530746	webdriver::server	DEBUG	-> GET /session/c415b86e-8ce2-40c6-b124-00ccaa988469/window/handles
[task 2022-03-01T15:28:50.749Z] 15:28:50     INFO - PID 1884 | 1646148530747	Marionette	DEBUG	0 -> [0,64,"WebDriver:GetWindowHandles",{}]
[task 2022-03-01T15:28:50.750Z] 15:28:50     INFO - PID 1884 | 1646148530747	Marionette	DEBUG	0 <- [1,64,null,["97f39bb2-f3f8-43bf-b093-60002209c73d"]]
[task 2022-03-01T15:28:50.750Z] 15:28:50     INFO - PID 1884 | 1646148530748	webdriver::server	DEBUG	<- 200 OK {"value":["97f39bb2-f3f8-43bf-b093-60002209c73d"]}
[task 2022-03-01T15:28:50.751Z] 15:28:50     INFO - PID 1884 | 1646148530749	webdriver::server	DEBUG	-> POST /session/c415b86e-8ce2-40c6-b124-00ccaa988469/window {"handle": "97f39bb2-f3f8-43bf-b093-60002209c73d"}
[task 2022-03-01T15:28:50.751Z] 15:28:50     INFO - PID 1884 | 1646148530749	Marionette	DEBUG	0 -> [0,65,"WebDriver:SwitchToWindow",{"handle":"97f39bb2-f3f8-43bf-b093-60002209c73d"}]
[task 2022-03-01T15:28:50.752Z] 15:28:50     INFO - PID 1884 | 1646148530751	Marionette	DEBUG	0 <- [1,65,null,{"value":null}]
[task 2022-03-01T15:28:50.753Z] 15:28:50     INFO - PID 1884 | 1646148530752	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2022-03-01T15:28:50.753Z] 15:28:50     INFO - PID 1884 | 1646148530752	webdriver::server	DEBUG	-> POST /session/c415b86e-8ce2-40c6-b124-00ccaa988469/alert/dismiss {}
[task 2022-03-01T15:28:50.754Z] 15:28:50     INFO - PID 1884 | 1646148530753	Marionette	DEBUG	0 -> [0,66,"WebDriver:DismissAlert",{}]
[task 2022-03-01T15:28:50.755Z] 15:28:50     INFO - PID 1884 | 1646148530754	Marionette	DEBUG	0 <- [1,66,{"error":"no such alert","message":"","stacktrace":"WebDriverError@chrome://remote/content/shared/webdriver/Errors.jsm: ... ote/content/marionette/server.js:253:9\n_onJSONObjectReady/<@chrome://remote/content/marionette/transport.js:500:20\n"},null]
[task 2022-03-01T15:28:50.756Z] 15:28:50     INFO - PID 1884 | 1646148530754	webdriver::server	DEBUG	<- 404 Not Found {"value":{"error":"no such alert","message":"","stacktrace":"WebDriverError@chrome://remote/content/shared/webdriver/Errors.jsm:183:5\nNoSuchAlertError@chrome://remote/content/shared/webdriver/Errors.jsm:384:5\nGeckoDriver.prototype._checkIfAlertIsPresent@chrome://remote/content/marionette/driver.js:2518:11\nGeckoDriver.prototype.dismissDialog@chrome://remote/content/marionette/driver.js:2419:8\ndespatch@chrome://remote/content/marionette/server.js:306:40\nexecute@chrome://remote/content/marionette/server.js:279:16\nonPacket/<@chrome://remote/content/marionette/server.js:252:20\nonPacket@chrome://remote/content/marionette/server.js:253:9\n_onJSONObjectReady/<@chrome://remote/content/marionette/transport.js:500:20\n"}}
[task 2022-03-01T15:28:50.756Z] 15:28:50     INFO - PID 1884 | 1646148530755	webdriver::server	DEBUG	-> POST /session/c415b86e-8ce2-40c6-b124-00ccaa988469/window {"handle": "97f39bb2-f3f8-43bf-b093-60002209c73d"}
[task 2022-03-01T15:28:50.757Z] 15:28:50     INFO - PID 1884 | 1646148530756	Marionette	DEBUG	0 -> [0,67,"WebDriver:SwitchToWindow",{"handle":"97f39bb2-f3f8-43bf-b093-60002209c73d"}]
[task 2022-03-01T15:28:50.758Z] 15:28:50     INFO - PID 1884 | 1646148530757	Marionette	DEBUG	0 <- [1,67,null,{"value":null}]
[task 2022-03-01T15:28:50.758Z] 15:28:50     INFO - PID 1884 | 1646148530757	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2022-03-01T15:28:50.759Z] 15:28:50     INFO - PID 1884 | 1646148530758	webdriver::server	DEBUG	-> GET /session/c415b86e-8ce2-40c6-b124-00ccaa988469/window
[task 2022-03-01T15:28:50.760Z] 15:28:50     INFO - PID 1884 | 1646148530759	Marionette	DEBUG	0 -> [0,68,"WebDriver:GetWindowHandle",{}]
[task 2022-03-01T15:28:50.760Z] 15:28:50     INFO - PID 1884 | 1646148530759	Marionette	DEBUG	0 <- [1,68,null,{"value":"97f39bb2-f3f8-43bf-b093-60002209c73d"}]
[task 2022-03-01T15:28:50.761Z] 15:28:50     INFO - PID 1884 | 1646148530760	webdriver::server	DEBUG	<- 200 OK {"value":"97f39bb2-f3f8-43bf-b093-60002209c73d"}
[task 2022-03-01T15:28:50.762Z] 15:28:50     INFO - PID 1884 | 1646148530760	webdriver::server	DEBUG	-> GET /session/c415b86e-8ce2-40c6-b124-00ccaa988469/window/handles
[task 2022-03-01T15:28:50.762Z] 15:28:50     INFO - PID 1884 | 1646148530761	Marionette	DEBUG	0 -> [0,69,"WebDriver:GetWindowHandles",{}]
[task 2022-03-01T15:28:50.763Z] 15:28:50     INFO - PID 1884 | 1646148530762	Marionette	DEBUG	0 <- [1,69,null,["97f39bb2-f3f8-43bf-b093-60002209c73d"]]
[task 2022-03-01T15:28:50.764Z] 15:28:50     INFO - PID 1884 | 1646148530762	webdriver::server	DEBUG	<- 200 OK {"value":["97f39bb2-f3f8-43bf-b093-60002209c73d"]}
[task 2022-03-01T15:28:50.764Z] 15:28:50     INFO - PID 1884 | 1646148530763	webdriver::server	DEBUG	-> POST /session/c415b86e-8ce2-40c6-b124-00ccaa988469/window {"handle": "97f39bb2-f3f8-43bf-b093-60002209c73d"}
[task 2022-03-01T15:28:50.765Z] 15:28:50     INFO - PID 1884 | 1646148530764	Marionette	DEBUG	0 -> [0,70,"WebDriver:SwitchToWindow",{"handle":"97f39bb2-f3f8-43bf-b093-60002209c73d"}]
[task 2022-03-01T15:28:50.766Z] 15:28:50     INFO - PID 1884 | 1646148530765	Marionette	DEBUG	0 <- [1,70,null,{"value":null}]
[task 2022-03-01T15:28:50.766Z] 15:28:50     INFO - PID 1884 | 1646148530765	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2022-03-01T15:28:50.767Z] 15:28:50     INFO - PID 1884 | 1646148530766	webdriver::server	DEBUG	-> POST /session/c415b86e-8ce2-40c6-b124-00ccaa988469/window/rect {"width": 800, "height": 600}
[task 2022-03-01T15:28:50.768Z] 15:28:50     INFO - PID 1884 | 1646148530767	Marionette	DEBUG	0 -> [0,71,"WebDriver:SetWindowRect",{"height":600,"width":800}]
[task 2022-03-01T15:28:50.769Z] 15:28:50     INFO - PID 1884 | 1646148530768	Marionette	DEBUG	0 <- [1,71,null,{"x":100,"y":100,"width":800,"height":600}]
[task 2022-03-01T15:28:50.769Z] 15:28:50     INFO - PID 1884 | 1646148530768	webdriver::server	DEBUG	<- 200 OK {"value":{"x":100,"y":100,"width":800,"height":600}}
[task 2022-03-01T15:28:50.770Z] 15:28:50     INFO - PID 1884 | 1646148530769	webdriver::server	DEBUG	-> POST /session/c415b86e-8ce2-40c6-b124-00ccaa988469/frame {"id": null}
[task 2022-03-01T15:28:50.770Z] 15:28:50     INFO - PID 1884 | 1646148530769	Marionette	DEBUG	0 -> [0,72,"WebDriver:SwitchToFrame",{"id":null}]
[task 2022-03-01T15:28:50.772Z] 15:28:50     INFO - PID 1884 | 1646148530772	Marionette	DEBUG	0 <- [1,72,null,{"value":null}]
[task 2022-03-01T15:28:50.773Z] 15:28:50     INFO - PID 1884 | 1646148530772	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2022-03-01T15:28:50.775Z] 15:28:50     INFO - STDOUT: tests/web-platform/tests/webdriver/tests/execute_async_script/execute_async.py::test_abort_by_user_prompt[alert] 
[task 2022-03-01T15:28:50.775Z] 15:28:50     INFO - PID 1884 | 1646148530774	webdriver::server	DEBUG	-> POST /session/c415b86e-8ce2-40c6-b124-00ccaa988469/window/rect {"width": 800, "height": 600}
[task 2022-03-01T15:28:50.776Z] 15:28:50     INFO - PID 1884 | 1646148530775	Marionette	DEBUG	0 -> [0,73,"WebDriver:SetWindowRect",{"height":600,"width":800}]
[task 2022-03-01T15:28:50.777Z] 15:28:50     INFO - PID 1884 | 1646148530775	Marionette	DEBUG	0 <- [1,73,null,{"x":100,"y":100,"width":800,"height":600}]
[task 2022-03-01T15:28:50.778Z] 15:28:50     INFO - PID 1884 | 1646148530776	webdriver::server	DEBUG	<- 200 OK {"value":{"x":100,"y":100,"width":800,"height":600}}
[task 2022-03-01T15:28:50.778Z] 15:28:50     INFO - PID 1884 | 1646148530776	webdriver::server	DEBUG	-> POST /session/c415b86e-8ce2-40c6-b124-00ccaa988469/window/rect {"x": 100, "y": 100}
[task 2022-03-01T15:28:50.778Z] 15:28:50     INFO - PID 1884 | 1646148530777	Marionette	DEBUG	0 -> [0,74,"WebDriver:SetWindowRect",{"x":100,"y":100}]
[task 2022-03-01T15:28:50.779Z] 15:28:50     INFO - PID 1884 | 1646148530778	Marionette	DEBUG	0 <- [1,74,null,{"x":100,"y":100,"width":800,"height":600}]
[task 2022-03-01T15:28:50.779Z] 15:28:50     INFO - PID 1884 | 1646148530779	webdriver::server	DEBUG	<- 200 OK {"value":{"x":100,"y":100,"width":800,"height":600}}
[task 2022-03-01T15:28:50.780Z] 15:28:50     INFO - PID 1884 | 1646148530780	webdriver::server	DEBUG	-> POST /session/c415b86e-8ce2-40c6-b124-00ccaa988469/execute/async {"script": "window.alert('Hello'); arguments[0](1);", "args": []}
[task 2022-03-01T15:28:50.781Z] 15:28:50     INFO - PID 1884 | 1646148530780	Marionette	DEBUG	0 -> [0,75,"WebDriver:ExecuteAsyncScript",{"args":[],"script":"window.alert('Hello'); arguments[0](1);"}]
[task 2022-03-01T15:28:50.862Z] 15:28:50     INFO - PID 1884 | [Parent 2098, Main Thread] WARNING: NS_ENSURE_TRUE(inst) failed: file StaticComponents.cpp:12116
[task 2022-03-01T15:28:50.865Z] 15:28:50     INFO - PID 1884 | JavaScript error: resource://gre/modules/XPCOMUtils.jsm, line 161: NS_ERROR_XPC_GS_RETURNED_FAILURE: ServiceManager::GetService returned failure code:
[task 2022-03-01T15:29:20.786Z] 15:29:20     INFO - PID 1884 | JavaScript error: chrome://remote/content/shared/webdriver/Errors.jsm, line 183: ScriptTimeoutError: Timed out after 30000 ms
[task 2022-03-01T15:30:07.382Z] 15:30:07     INFO - TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/execute_async_script/execute_async.py | expected OK
[task 2022-03-01T15:30:07.383Z] 15:30:07     INFO - TEST-INFO took 80002ms
[task 2022-03-01T15:30:07.419Z] 15:30:07  WARNING - Firefox didn't exit cleanly, not processing leak logs
[task 2022-03-01T15:30:07.514Z] 15:30:07     INFO - Closing logging queue
[task 2022-03-01T15:30:07.514Z] 15:30:07     INFO - queue closed
[task 2022-03-01T15:30:07.523Z] 15:30:07     INFO - PID 2317 | 1646148607521	geckodriver	INFO	Listening on 127.0.0.1:58454
[task 2022-03-01T15:30:07.523Z] 15:30:07     INFO - Starting runner
[task 2022-03-01T15:30:07.759Z] 15:30:07     INFO - TEST-START | /webdriver/tests/execute_async_script/promise.py

As it looks like Firefox failed to open an alert() or our registered modal observer didn't notice it. Nothing has changed in that area for a while. So lets see how often this failure happens.

Actually maybe similar to bug 1757561 but without such a clear failure message.

See Also: → 1757561

I would say it's a dupe based on other similarly failing tests. If it still happens after the backout feel free to reopen.

Status: NEW → RESOLVED
Closed: 3 years ago
Resolution: --- → DUPLICATE
See Also: 1757561
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.