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)
Remote Protocol
Marionette
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
See Also: → 1757625
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
Comment 4•2 years ago
|
||
Moving bug to Remote Protocol::Marionette component per bug 1815831.
Component: geckodriver → Marionette
Product: Testing → Remote Protocol
You need to log in
before you can comment on or make changes to this bug.
Description
•