Closed
Bug 1755367
Opened 3 years ago
Closed 3 years ago
Intermittent TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/execute_script/execute.py | expected OK
Categories
(Remote Protocol :: Marionette, defect, P5)
Remote Protocol
Marionette
Tracking
(Not tracked)
RESOLVED
DUPLICATE
of bug 1630162
People
(Reporter: intermittent-bug-filer, Unassigned)
Details
(Keywords: intermittent-failure)
Filed by: ctuns [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=367834703&repo=mozilla-central
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/H8j0yTs7Q92UBpr7ecFj4g/runs/0/artifacts/public/logs/live_backing.log
[task 2022-02-14T19:49:51.958Z] 19:49:51 INFO - STDOUT: PASSED
[task 2022-02-14T19:49:51.959Z] 19:49:51 INFO - PID 1312 | 1644868191958 webdriver::server DEBUG -> POST /session/9dea65b4-f99b-4b27-ab9d-4036b165b81e/timeouts {"implicit": 0}
[task 2022-02-14T19:49:51.960Z] 19:49:51 INFO - PID 1312 | 1644868191959 Marionette DEBUG 0 -> [0,241,"WebDriver:SetTimeouts",{"implicit":0}]
[task 2022-02-14T19:49:51.961Z] 19:49:51 INFO - PID 1312 | 1644868191960 Marionette DEBUG 0 <- [1,241,null,{"value":null}]
[task 2022-02-14T19:49:51.961Z] 19:49:51 INFO - PID 1312 | 1644868191960 webdriver::server DEBUG <- 200 OK {"value":null}
[task 2022-02-14T19:49:51.962Z] 19:49:51 INFO - PID 1312 | 1644868191961 webdriver::server DEBUG -> POST /session/9dea65b4-f99b-4b27-ab9d-4036b165b81e/timeouts {"pageLoad": 300000}
[task 2022-02-14T19:49:51.963Z] 19:49:51 INFO - PID 1312 | 1644868191962 Marionette DEBUG 0 -> [0,242,"WebDriver:SetTimeouts",{"pageLoad":300000}]
[task 2022-02-14T19:49:51.963Z] 19:49:51 INFO - PID 1312 | 1644868191962 Marionette DEBUG 0 <- [1,242,null,{"value":null}]
[task 2022-02-14T19:49:51.964Z] 19:49:51 INFO - PID 1312 | 1644868191962 webdriver::server DEBUG <- 200 OK {"value":null}
[task 2022-02-14T19:49:51.965Z] 19:49:51 INFO - PID 1312 | 1644868191964 webdriver::server DEBUG -> POST /session/9dea65b4-f99b-4b27-ab9d-4036b165b81e/timeouts {"script": 30000}
[task 2022-02-14T19:49:51.965Z] 19:49:51 INFO - PID 1312 | 1644868191964 Marionette DEBUG 0 -> [0,243,"WebDriver:SetTimeouts",{"script":30000}]
[task 2022-02-14T19:49:51.966Z] 19:49:51 INFO - PID 1312 | 1644868191965 Marionette DEBUG 0 <- [1,243,null,{"value":null}]
[task 2022-02-14T19:49:51.967Z] 19:49:51 INFO - PID 1312 | 1644868191965 webdriver::server DEBUG <- 200 OK {"value":null}
[task 2022-02-14T19:49:51.968Z] 19:49:51 INFO - PID 1312 | 1644868191966 webdriver::server DEBUG -> GET /session/9dea65b4-f99b-4b27-ab9d-4036b165b81e/window
[task 2022-02-14T19:49:51.969Z] 19:49:51 INFO - PID 1312 | 1644868191966 Marionette DEBUG 0 -> [0,244,"WebDriver:GetWindowHandle",{}]
[task 2022-02-14T19:49:51.969Z] 19:49:51 INFO - PID 1312 | 1644868191967 Marionette DEBUG 0 <- [1,244,null,{"value":"524b6f89-380e-41e8-8645-118c5fe897de"}]
[task 2022-02-14T19:49:51.970Z] 19:49:51 INFO - PID 1312 | 1644868191968 webdriver::server DEBUG <- 200 OK {"value":"524b6f89-380e-41e8-8645-118c5fe897de"}
[task 2022-02-14T19:49:51.971Z] 19:49:51 INFO - PID 1312 | 1644868191969 webdriver::server DEBUG -> GET /session/9dea65b4-f99b-4b27-ab9d-4036b165b81e/window
[task 2022-02-14T19:49:51.971Z] 19:49:51 INFO - PID 1312 | 1644868191970 Marionette DEBUG 0 -> [0,245,"WebDriver:GetWindowHandle",{}]
[task 2022-02-14T19:49:51.972Z] 19:49:51 INFO - PID 1312 | 1644868191970 Marionette DEBUG 0 <- [1,245,null,{"value":"524b6f89-380e-41e8-8645-118c5fe897de"}]
[task 2022-02-14T19:49:51.973Z] 19:49:51 INFO - PID 1312 | 1644868191971 webdriver::server DEBUG <- 200 OK {"value":"524b6f89-380e-41e8-8645-118c5fe897de"}
[task 2022-02-14T19:49:51.974Z] 19:49:51 INFO - PID 1312 | 1644868191972 webdriver::server DEBUG -> GET /session/9dea65b4-f99b-4b27-ab9d-4036b165b81e/window/handles
[task 2022-02-14T19:49:51.974Z] 19:49:51 INFO - PID 1312 | 1644868191972 Marionette DEBUG 0 -> [0,246,"WebDriver:GetWindowHandles",{}]
[task 2022-02-14T19:49:51.975Z] 19:49:51 INFO - PID 1312 | 1644868191972 Marionette DEBUG 0 <- [1,246,null,["524b6f89-380e-41e8-8645-118c5fe897de"]]
[task 2022-02-14T19:49:51.976Z] 19:49:51 INFO - PID 1312 | 1644868191973 webdriver::server DEBUG <- 200 OK {"value":["524b6f89-380e-41e8-8645-118c5fe897de"]}
[task 2022-02-14T19:49:51.976Z] 19:49:51 INFO - PID 1312 | 1644868191974 webdriver::server DEBUG -> POST /session/9dea65b4-f99b-4b27-ab9d-4036b165b81e/window {"handle": "524b6f89-380e-41e8-8645-118c5fe897de"}
[task 2022-02-14T19:49:51.977Z] 19:49:51 INFO - PID 1312 | 1644868191974 Marionette DEBUG 0 -> [0,247,"WebDriver:SwitchToWindow",{"handle":"524b6f89-380e-41e8-8645-118c5fe897de"}]
[task 2022-02-14T19:49:51.978Z] 19:49:51 INFO - PID 1312 | 1644868191975 Marionette DEBUG 0 <- [1,247,null,{"value":null}]
[task 2022-02-14T19:49:51.978Z] 19:49:51 INFO - PID 1312 | 1644868191976 webdriver::server DEBUG <- 200 OK {"value":null}
[task 2022-02-14T19:49:51.979Z] 19:49:51 INFO - PID 1312 | 1644868191977 webdriver::server DEBUG -> POST /session/9dea65b4-f99b-4b27-ab9d-4036b165b81e/alert/dismiss {}
[task 2022-02-14T19:49:51.980Z] 19:49:51 INFO - PID 1312 | 1644868191977 Marionette DEBUG 0 -> [0,248,"WebDriver:DismissAlert",{}]
[task 2022-02-14T19:49:51.981Z] 19:49:51 INFO - PID 1312 | 1644868191978 Marionette DEBUG 0 <- [1,248,{"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-02-14T19:49:51.983Z] 19:49:51 INFO - PID 1312 | 1644868191978 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-02-14T19:49:51.984Z] 19:49:51 INFO - PID 1312 | 1644868191979 webdriver::server DEBUG -> POST /session/9dea65b4-f99b-4b27-ab9d-4036b165b81e/window {"handle": "524b6f89-380e-41e8-8645-118c5fe897de"}
[task 2022-02-14T19:49:51.985Z] 19:49:51 INFO - PID 1312 | 1644868191980 Marionette DEBUG 0 -> [0,249,"WebDriver:SwitchToWindow",{"handle":"524b6f89-380e-41e8-8645-118c5fe897de"}]
[task 2022-02-14T19:49:51.985Z] 19:49:51 INFO - PID 1312 | 1644868191981 Marionette DEBUG 0 <- [1,249,null,{"value":null}]
[task 2022-02-14T19:49:51.986Z] 19:49:51 INFO - PID 1312 | 1644868191981 webdriver::server DEBUG <- 200 OK {"value":null}
[task 2022-02-14T19:49:51.987Z] 19:49:51 INFO - PID 1312 | 1644868191983 webdriver::server DEBUG -> GET /session/9dea65b4-f99b-4b27-ab9d-4036b165b81e/window
[task 2022-02-14T19:49:51.987Z] 19:49:51 INFO - PID 1312 | 1644868191984 Marionette DEBUG 0 -> [0,250,"WebDriver:GetWindowHandle",{}]
[task 2022-02-14T19:49:51.988Z] 19:49:51 INFO - PID 1312 | 1644868191984 Marionette DEBUG 0 <- [1,250,null,{"value":"524b6f89-380e-41e8-8645-118c5fe897de"}]
[task 2022-02-14T19:49:51.989Z] 19:49:51 INFO - PID 1312 | 1644868191985 webdriver::server DEBUG <- 200 OK {"value":"524b6f89-380e-41e8-8645-118c5fe897de"}
[task 2022-02-14T19:49:51.989Z] 19:49:51 INFO - PID 1312 | 1644868191985 webdriver::server DEBUG -> GET /session/9dea65b4-f99b-4b27-ab9d-4036b165b81e/window/handles
[task 2022-02-14T19:49:51.990Z] 19:49:51 INFO - PID 1312 | 1644868191986 Marionette DEBUG 0 -> [0,251,"WebDriver:GetWindowHandles",{}]
[task 2022-02-14T19:49:51.991Z] 19:49:51 INFO - PID 1312 | 1644868191987 Marionette DEBUG 0 <- [1,251,null,["524b6f89-380e-41e8-8645-118c5fe897de"]]
[task 2022-02-14T19:49:51.992Z] 19:49:51 INFO - PID 1312 | 1644868191987 webdriver::server DEBUG <- 200 OK {"value":["524b6f89-380e-41e8-8645-118c5fe897de"]}
[task 2022-02-14T19:49:51.992Z] 19:49:51 INFO - PID 1312 | 1644868191988 webdriver::server DEBUG -> POST /session/9dea65b4-f99b-4b27-ab9d-4036b165b81e/window {"handle": "524b6f89-380e-41e8-8645-118c5fe897de"}
[task 2022-02-14T19:49:51.993Z] 19:49:51 INFO - PID 1312 | 1644868191988 Marionette DEBUG 0 -> [0,252,"WebDriver:SwitchToWindow",{"handle":"524b6f89-380e-41e8-8645-118c5fe897de"}]
[task 2022-02-14T19:49:51.994Z] 19:49:51 INFO - PID 1312 | 1644868191989 Marionette DEBUG 0 <- [1,252,null,{"value":null}]
[task 2022-02-14T19:49:51.994Z] 19:49:51 INFO - PID 1312 | 1644868191990 webdriver::server DEBUG <- 200 OK {"value":null}
[task 2022-02-14T19:49:51.995Z] 19:49:51 INFO - PID 1312 | 1644868191991 webdriver::server DEBUG -> POST /session/9dea65b4-f99b-4b27-ab9d-4036b165b81e/window/rect {"width": 800, "height": 600}
[task 2022-02-14T19:49:51.996Z] 19:49:51 INFO - PID 1312 | 1644868191992 Marionette DEBUG 0 -> [0,253,"WebDriver:SetWindowRect",{"height":600,"width":800}]
[task 2022-02-14T19:49:51.996Z] 19:49:51 INFO - PID 1312 | 1644868191992 Marionette DEBUG 0 <- [1,253,null,{"x":100,"y":100,"width":800,"height":600}]
[task 2022-02-14T19:49:51.997Z] 19:49:51 INFO - PID 1312 | 1644868191993 webdriver::server DEBUG <- 200 OK {"value":{"x":100,"y":100,"width":800,"height":600}}
[task 2022-02-14T19:49:51.997Z] 19:49:51 INFO - PID 1312 | 1644868191994 webdriver::server DEBUG -> POST /session/9dea65b4-f99b-4b27-ab9d-4036b165b81e/frame {"id": null}
[task 2022-02-14T19:49:51.998Z] 19:49:51 INFO - PID 1312 | 1644868191994 Marionette DEBUG 0 -> [0,254,"WebDriver:SwitchToFrame",{"id":null}]
[task 2022-02-14T19:49:51.999Z] 19:49:51 INFO - PID 1312 | 1644868191996 Marionette DEBUG 0 <- [1,254,null,{"value":null}]
[task 2022-02-14T19:49:51.999Z] 19:49:51 INFO - PID 1312 | 1644868191996 webdriver::server DEBUG <- 200 OK {"value":null}
[task 2022-02-14T19:49:52.000Z] 19:49:52 INFO - PID 1312 | 1644868192000 webdriver::server DEBUG -> DELETE /session/9dea65b4-f99b-4b27-ab9d-4036b165b81e
[task 2022-02-14T19:49:52.001Z] 19:49:52 INFO - PID 1312 | 1644868192000 Marionette DEBUG 0 -> [0,255,"Marionette:Quit",{"flags":["eForceQuit"]}]
[task 2022-02-14T19:49:52.002Z] 19:49:52 INFO - PID 1312 | 1644868192001 Marionette INFO Stopped listening on port 54285
[task 2022-02-14T19:49:52.078Z] 19:49:52 INFO - PID 1312 | 1644868192081 Marionette TRACE Received observer notification quit-application
[task 2022-02-14T19:49:52.083Z] 19:49:52 INFO - PID 1312 | 1644868192081 Marionette TRACE Received observer notification quit-application
[task 2022-02-14T19:49:52.084Z] 19:49:52 INFO - PID 1312 | 1644868192082 Marionette DEBUG Marionette stopped listening
[task 2022-02-14T19:49:52.086Z] 19:49:52 INFO - PID 1312 | 1644868192085 Marionette DEBUG 0 <- [1,255,null,{"cause":"shutdown","forced":false}]
[task 2022-02-14T19:49:52.114Z] 19:49:52 INFO - PID 1312 | 1644868192118 webdriver::server DEBUG Teardown session
[task 2022-02-14T19:49:52.120Z] 19:49:52 INFO - PID 1312 | JavaScript error: resource://gre/modules/URLQueryStrippingListService.jsm, line 90: TypeError: can't access property "removeEventListener", Services.cpmm.sharedData is null
[task 2022-02-14T19:49:52.122Z] 19:49:52 INFO - PID 1312 | 1644868192122 Marionette DEBUG Closed connection 0
[task 2022-02-14T19:49:52.131Z] 19:49:52 INFO - PID 1312 | ###!!! [Parent][PCompositorManagerParent] Error: RunMessage(msgname=PCompositorBridge::Msg___delete__) Channel closing: too late to send/recv, messages will be lost
[task 2022-02-14T19:49:52.134Z] 19:49:52 INFO - PID 1312 | ###!!! [Parent][PCompositorManagerParent] Error: RunMessage(msgname=PCompositorBridge::Msg___delete__) Channel closing: too late to send/recv, messages will be lost
[task 2022-02-14T19:49:55.749Z] 19:49:55 INFO - PID 1312 | JavaScript error: resource://gre/modules/URLQueryStrippingListService.jsm, line 90: TypeError: can't access property "removeEventListener", Services.cpmm.sharedData is null
[task 2022-02-14T19:49:55.749Z] 19:49:55 INFO - PID 1312 | ###!!! [Parent][PCompositorManagerParent] Error: RunMessage(msgname=PCompositorBridge::Msg___delete__) Channel closing: too late to send/recv, messages will be lost
[task 2022-02-14T19:49:55.749Z] 19:49:55 INFO - PID 1312 | ###!!! [Parent][PImageBridgeParent] Error: RunMessage(msgname=PImageBridge::Msg_WillClose) Channel closing: too late to send/recv, messages will be lost
[task 2022-02-14T19:49:55.749Z] 19:49:55 INFO - PID 1312 | ###!!! [Parent][PCompositorManagerParent] Error: RunMessage(msgname=PCompositorBridge::Msg___delete__) Channel closing: too late to send/recv, messages will be lost
[task 2022-02-14T19:49:55.749Z] 19:49:55 INFO - PID 1312 | ###!!! [Parent][PCompositorManagerParent] Error: RunMessage(msgname=PCompositorBridge::Msg___delete__) Channel closing: too late to send/recv, messages will be lost
[task 2022-02-14T19:49:55.762Z] 19:49:55 INFO - PID 1312 | ###!!! [Parent][PCompositorManagerParent] Error: RunMessage(msgname=PCompositorBridge::Msg___delete__) Channel closing: too late to send/recv, messages will be lost
[task 2022-02-14T19:50:07.091Z] 19:50:07 INFO - PID 1312 | console.error: (new Error("SessionFile is closed", "resource:///modules/sessionstore/SessionFile.jsm", 443))
[task 2022-02-14T19:50:19.083Z] 19:50:19 INFO - PID 1312 | ###!!! [Parent][PGPUParent] Error: RunMessage(msgname=PGPU::Msg_ShutdownVR) Channel closing: too late to send/recv, messages will be lost
[task 2022-02-14T19:50:19.985Z] 19:50:19 INFO - PID 1312 | Waiting in WillDestroyCurrentMessageLoop for pid 3648
[task 2022-02-14T19:50:37.477Z] 19:50:37 INFO - TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/execute_script/execute.py | expected OK
[task 2022-02-14T19:50:37.477Z] 19:50:37 INFO - TEST-INFO took 55015ms
[task 2022-02-14T19:50:48.495Z] 19:50:48 INFO - PID 1312 | 1644868248495 geckodriver::browser DEBUG Browser process stopped: exit code: 0
[task 2022-02-14T19:50:48.497Z] 19:50:48 INFO - PID 1312 | 1644868248496 webdriver::server DEBUG <- 200 OK {"value":null}
[task 2022-02-14T19:50:48.499Z] 19:50:48 INFO - PID 1312 | 1644868248497 webdriver::server DEBUG -> GET /status
[task 2022-02-14T19:50:48.500Z] 19:50:48 INFO - PID 1312 | 1644868248497 webdriver::server DEBUG <- 200 OK {"value":{"message":"","ready":true}}
[task 2022-02-14T19:50:48.544Z] 19:50:48 INFO - Closing logging queue
[task 2022-02-14T19:50:48.553Z] 19:50:48 INFO - queue closed
[task 2022-02-14T19:50:49.066Z] 19:50:49 INFO - PID 8624 | 1644868248566 geckodriver INFO Listening on 127.0.0.1:49811
[task 2022-02-14T19:50:49.069Z] 19:50:49 INFO - Starting runner
[task 2022-02-14T19:50:49.613Z] 19:50:49 INFO - TEST-START | /webdriver/tests/execute_script/json_serialize_windowproxy.py
|
||
Comment 1•3 years ago
|
||
There is a hang during the shutdown of Firefox:
[task 2022-02-14T19:49:55.749Z] 19:49:55 INFO - PID 1312 | ###!!! [Parent][PCompositorManagerParent] Error: RunMessage(msgname=PCompositorBridge::Msg___delete__) Channel closing: too late to send/recv, messages will be lost
[task 2022-02-14T19:49:55.762Z] 19:49:55 INFO - PID 1312 | ###!!! [Parent][PCompositorManagerParent] Error: RunMessage(msgname=PCompositorBridge::Msg___delete__) Channel closing: too late to send/recv, messages will be lost
[task 2022-02-14T19:50:07.091Z] 19:50:07 INFO - PID 1312 | console.error: (new Error("SessionFile is closed", "resource:///modules/sessionstore/SessionFile.jsm", 443))
[task 2022-02-14T19:50:19.083Z] 19:50:19 INFO - PID 1312 | ###!!! [Parent][PGPUParent] Error: RunMessage(msgname=PGPU::Msg_ShutdownVR) Channel closing: too late to send/recv, messages will be lost
[task 2022-02-14T19:50:19.985Z] 19:50:19 INFO - PID 1312 | Waiting in WillDestroyCurrentMessageLoop for pid 3648
[task 2022-02-14T19:50:37.477Z] 19:50:37 INFO - TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/execute_script/execute.py | expected OK
Status: NEW → RESOLVED
Closed: 3 years ago
Resolution: --- → DUPLICATE
|
||
Comment 2•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
•