Closed
Bug 1746511
Opened 3 years ago
Closed 3 years ago
Intermittent [tier 2] TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/minimize_window/user_prompts.py | expected OK
Categories
(Remote Protocol :: Marionette, defect, P5)
Remote Protocol
Marionette
Tracking
(Not tracked)
RESOLVED
INCOMPLETE
People
(Reporter: intermittent-bug-filer, Unassigned)
References
(Blocks 1 open bug)
Details
(Keywords: intermittent-failure)
Filed by: ctuns [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=361525121&repo=mozilla-central
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/anLtdbA-SPmwhKNvUzS-Pw/runs/0/artifacts/public/logs/live_backing.log
[task 2021-12-16T21:01:08.605Z] 21:01:08 INFO - STDOUT: PASSED
[task 2021-12-16T21:01:08.609Z] 21:01:08 INFO - PID 6800 | 1639688468607 webdriver::server DEBUG -> POST /session/e6afa167-c870-4010-80bd-bd0d9963fd95/timeouts {"implicit": 0}
[task 2021-12-16T21:01:08.610Z] 21:01:08 INFO - PID 6800 | 1639688468608 Marionette DEBUG 0 -> [0,216,"WebDriver:SetTimeouts",{"implicit":0}]
[task 2021-12-16T21:01:08.611Z] 21:01:08 INFO - PID 6800 | 1639688468609 Marionette DEBUG 0 <- [1,216,null,{"value":null}]
[task 2021-12-16T21:01:08.612Z] 21:01:08 INFO - PID 6800 | 1639688468610 webdriver::server DEBUG <- 200 OK {"value":null}
[task 2021-12-16T21:01:08.613Z] 21:01:08 INFO - PID 6800 | 1639688468611 webdriver::server DEBUG -> POST /session/e6afa167-c870-4010-80bd-bd0d9963fd95/timeouts {"pageLoad": 300000}
[task 2021-12-16T21:01:08.614Z] 21:01:08 INFO - PID 6800 | 1639688468612 Marionette DEBUG 0 -> [0,217,"WebDriver:SetTimeouts",{"pageLoad":300000}]
[task 2021-12-16T21:01:08.615Z] 21:01:08 INFO - PID 6800 | 1639688468612 Marionette DEBUG 0 <- [1,217,null,{"value":null}]
[task 2021-12-16T21:01:08.616Z] 21:01:08 INFO - PID 6800 | 1639688468613 webdriver::server DEBUG <- 200 OK {"value":null}
[task 2021-12-16T21:01:08.617Z] 21:01:08 INFO - PID 6800 | 1639688468614 webdriver::server DEBUG -> POST /session/e6afa167-c870-4010-80bd-bd0d9963fd95/timeouts {"script": 30000}
[task 2021-12-16T21:01:08.617Z] 21:01:08 INFO - PID 6800 | 1639688468614 Marionette DEBUG 0 -> [0,218,"WebDriver:SetTimeouts",{"script":30000}]
[task 2021-12-16T21:01:08.618Z] 21:01:08 INFO - PID 6800 | 1639688468615 Marionette DEBUG 0 <- [1,218,null,{"value":null}]
[task 2021-12-16T21:01:08.619Z] 21:01:08 INFO - PID 6800 | 1639688468615 webdriver::server DEBUG <- 200 OK {"value":null}
[task 2021-12-16T21:01:08.620Z] 21:01:08 INFO - PID 6800 | 1639688468616 webdriver::server DEBUG -> GET /session/e6afa167-c870-4010-80bd-bd0d9963fd95/window
[task 2021-12-16T21:01:08.621Z] 21:01:08 INFO - PID 6800 | 1639688468617 Marionette DEBUG 0 -> [0,219,"WebDriver:GetWindowHandle",{}]
[task 2021-12-16T21:01:08.622Z] 21:01:08 INFO - PID 6800 | 1639688468618 Marionette DEBUG 0 <- [1,219,null,{"value":"06ad9421-46c1-4086-a3cf-ee7633fbed07"}]
[task 2021-12-16T21:01:08.623Z] 21:01:08 INFO - PID 6800 | 1639688468618 webdriver::server DEBUG <- 200 OK {"value":"06ad9421-46c1-4086-a3cf-ee7633fbed07"}
[task 2021-12-16T21:01:08.624Z] 21:01:08 INFO - PID 6800 | 1639688468619 webdriver::server DEBUG -> GET /session/e6afa167-c870-4010-80bd-bd0d9963fd95/window
[task 2021-12-16T21:01:08.625Z] 21:01:08 INFO - PID 6800 | 1639688468620 Marionette DEBUG 0 -> [0,220,"WebDriver:GetWindowHandle",{}]
[task 2021-12-16T21:01:08.626Z] 21:01:08 INFO - PID 6800 | 1639688468620 Marionette DEBUG 0 <- [1,220,null,{"value":"06ad9421-46c1-4086-a3cf-ee7633fbed07"}]
[task 2021-12-16T21:01:08.627Z] 21:01:08 INFO - PID 6800 | 1639688468620 webdriver::server DEBUG <- 200 OK {"value":"06ad9421-46c1-4086-a3cf-ee7633fbed07"}
[task 2021-12-16T21:01:08.628Z] 21:01:08 INFO - PID 6800 | 1639688468621 webdriver::server DEBUG -> GET /session/e6afa167-c870-4010-80bd-bd0d9963fd95/window/handles
[task 2021-12-16T21:01:08.629Z] 21:01:08 INFO - PID 6800 | 1639688468623 Marionette DEBUG 0 -> [0,221,"WebDriver:GetWindowHandles",{}]
[task 2021-12-16T21:01:08.630Z] 21:01:08 INFO - PID 6800 | 1639688468623 Marionette DEBUG 0 <- [1,221,null,["06ad9421-46c1-4086-a3cf-ee7633fbed07"]]
[task 2021-12-16T21:01:08.630Z] 21:01:08 INFO - PID 6800 | 1639688468624 webdriver::server DEBUG <- 200 OK {"value":["06ad9421-46c1-4086-a3cf-ee7633fbed07"]}
[task 2021-12-16T21:01:08.631Z] 21:01:08 INFO - PID 6800 | 1639688468625 webdriver::server DEBUG -> POST /session/e6afa167-c870-4010-80bd-bd0d9963fd95/window {"handle": "06ad9421-46c1-4086-a3cf-ee7633fbed07"}
[task 2021-12-16T21:01:08.632Z] 21:01:08 INFO - PID 6800 | 1639688468625 Marionette DEBUG 0 -> [0,222,"WebDriver:SwitchToWindow",{"handle":"06ad9421-46c1-4086-a3cf-ee7633fbed07"}]
[task 2021-12-16T21:01:08.633Z] 21:01:08 INFO - PID 6800 | 1639688468627 Marionette DEBUG 0 <- [1,222,null,{"value":null}]
[task 2021-12-16T21:01:08.635Z] 21:01:08 INFO - PID 6800 | 1639688468627 webdriver::server DEBUG <- 200 OK {"value":null}
[task 2021-12-16T21:01:08.636Z] 21:01:08 INFO - PID 6800 | 1639688468628 webdriver::server DEBUG -> POST /session/e6afa167-c870-4010-80bd-bd0d9963fd95/alert/dismiss {}
[task 2021-12-16T21:01:08.637Z] 21:01:08 INFO - PID 6800 | 1639688468629 Marionette DEBUG 0 -> [0,223,"WebDriver:DismissAlert",{}]
[task 2021-12-16T21:01:08.638Z] 21:01:08 INFO - PID 6800 | 1639688468630 Marionette DEBUG 0 <- [1,223,{"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 2021-12-16T21:01:08.640Z] 21:01:08 INFO - PID 6800 | 1639688468630 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:2575:11\nGeckoDriver.prototype.dismissDialog@chrome://remote/content/marionette/driver.js:2476: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 2021-12-16T21:01:08.641Z] 21:01:08 INFO - PID 6800 | 1639688468631 webdriver::server DEBUG -> POST /session/e6afa167-c870-4010-80bd-bd0d9963fd95/window {"handle": "06ad9421-46c1-4086-a3cf-ee7633fbed07"}
[task 2021-12-16T21:01:08.642Z] 21:01:08 INFO - PID 6800 | 1639688468632 Marionette DEBUG 0 -> [0,224,"WebDriver:SwitchToWindow",{"handle":"06ad9421-46c1-4086-a3cf-ee7633fbed07"}]
[task 2021-12-16T21:01:08.643Z] 21:01:08 INFO - PID 6800 | 1639688468633 Marionette DEBUG 0 <- [1,224,null,{"value":null}]
[task 2021-12-16T21:01:08.644Z] 21:01:08 INFO - PID 6800 | 1639688468634 webdriver::server DEBUG <- 200 OK {"value":null}
[task 2021-12-16T21:01:08.644Z] 21:01:08 INFO - PID 6800 | 1639688468635 webdriver::server DEBUG -> GET /session/e6afa167-c870-4010-80bd-bd0d9963fd95/window
[task 2021-12-16T21:01:08.645Z] 21:01:08 INFO - PID 6800 | 1639688468635 Marionette DEBUG 0 -> [0,225,"WebDriver:GetWindowHandle",{}]
[task 2021-12-16T21:01:08.646Z] 21:01:08 INFO - PID 6800 | 1639688468636 Marionette DEBUG 0 <- [1,225,null,{"value":"06ad9421-46c1-4086-a3cf-ee7633fbed07"}]
[task 2021-12-16T21:01:08.647Z] 21:01:08 INFO - PID 6800 | 1639688468636 webdriver::server DEBUG <- 200 OK {"value":"06ad9421-46c1-4086-a3cf-ee7633fbed07"}
[task 2021-12-16T21:01:08.648Z] 21:01:08 INFO - PID 6800 | 1639688468637 webdriver::server DEBUG -> GET /session/e6afa167-c870-4010-80bd-bd0d9963fd95/window/handles
[task 2021-12-16T21:01:08.649Z] 21:01:08 INFO - PID 6800 | 1639688468638 Marionette DEBUG 0 -> [0,226,"WebDriver:GetWindowHandles",{}]
[task 2021-12-16T21:01:08.650Z] 21:01:08 INFO - PID 6800 | 1639688468638 Marionette DEBUG 0 <- [1,226,null,["06ad9421-46c1-4086-a3cf-ee7633fbed07"]]
[task 2021-12-16T21:01:08.651Z] 21:01:08 INFO - PID 6800 | 1639688468639 webdriver::server DEBUG <- 200 OK {"value":["06ad9421-46c1-4086-a3cf-ee7633fbed07"]}
[task 2021-12-16T21:01:08.652Z] 21:01:08 INFO - PID 6800 | 1639688468640 webdriver::server DEBUG -> POST /session/e6afa167-c870-4010-80bd-bd0d9963fd95/window {"handle": "06ad9421-46c1-4086-a3cf-ee7633fbed07"}
[task 2021-12-16T21:01:08.653Z] 21:01:08 INFO - PID 6800 | 1639688468640 Marionette DEBUG 0 -> [0,227,"WebDriver:SwitchToWindow",{"handle":"06ad9421-46c1-4086-a3cf-ee7633fbed07"}]
[task 2021-12-16T21:01:08.654Z] 21:01:08 INFO - PID 6800 | 1639688468642 Marionette DEBUG 0 <- [1,227,null,{"value":null}]
[task 2021-12-16T21:01:08.655Z] 21:01:08 INFO - PID 6800 | 1639688468642 webdriver::server DEBUG <- 200 OK {"value":null}
[task 2021-12-16T21:01:08.656Z] 21:01:08 INFO - PID 6800 | 1639688468643 webdriver::server DEBUG -> POST /session/e6afa167-c870-4010-80bd-bd0d9963fd95/window/rect {"width": 800, "height": 600}
[task 2021-12-16T21:01:08.657Z] 21:01:08 INFO - PID 6800 | 1639688468644 Marionette DEBUG 0 -> [0,228,"WebDriver:SetWindowRect",{"height":600,"width":800}]
[task 2021-12-16T21:01:08.658Z] 21:01:08 INFO - PID 6800 | 1639688468645 Marionette DEBUG 0 <- [1,228,null,{"x":100,"y":100,"width":800,"height":600}]
[task 2021-12-16T21:01:08.659Z] 21:01:08 INFO - PID 6800 | 1639688468645 webdriver::server DEBUG <- 200 OK {"value":{"x":100,"y":100,"width":800,"height":600}}
[task 2021-12-16T21:01:08.660Z] 21:01:08 INFO - PID 6800 | 1639688468646 webdriver::server DEBUG -> POST /session/e6afa167-c870-4010-80bd-bd0d9963fd95/frame {"id": null}
[task 2021-12-16T21:01:08.660Z] 21:01:08 INFO - PID 6800 | 1639688468647 Marionette DEBUG 0 -> [0,229,"WebDriver:SwitchToFrame",{"id":null}]
[task 2021-12-16T21:01:08.661Z] 21:01:08 INFO - PID 6800 | 1639688468649 Marionette DEBUG 0 <- [1,229,null,{"value":null}]
[task 2021-12-16T21:01:08.663Z] 21:01:08 INFO - PID 6800 | 1639688468649 webdriver::server DEBUG <- 200 OK {"value":null}
[task 2021-12-16T21:01:08.664Z] 21:01:08 INFO - STDOUT: tests/web-platform/tests/webdriver/tests/minimize_window/user_prompts.py::test_default[alert-None]
[task 2021-12-16T21:01:08.664Z] 21:01:08 INFO - PID 6800 | 1639688468653 webdriver::server DEBUG -> DELETE /session/e6afa167-c870-4010-80bd-bd0d9963fd95
[task 2021-12-16T21:01:08.665Z] 21:01:08 INFO - PID 6800 | 1639688468653 Marionette DEBUG 0 -> [0,230,"Marionette:Quit",{"flags":["eForceQuit"]}]
[task 2021-12-16T21:01:08.667Z] 21:01:08 INFO - PID 6800 | 1639688468654 Marionette INFO Stopped listening on port 2828
[task 2021-12-16T21:01:08.742Z] 21:01:08 INFO - PID 6800 | 1639688468750 Marionette TRACE Received observer notification quit-application
[task 2021-12-16T21:01:08.752Z] 21:01:08 INFO - PID 6800 | 1639688468750 Marionette TRACE Received observer notification quit-application
[task 2021-12-16T21:01:08.753Z] 21:01:08 INFO - PID 6800 | 1639688468750 Marionette DEBUG Marionette stopped listening
[task 2021-12-16T21:01:08.757Z] 21:01:08 INFO - PID 6800 | 1639688468756 Marionette DEBUG 0 <- [1,230,null,{"cause":"shutdown","forced":false}]
[task 2021-12-16T21:01:08.785Z] 21:01:08 INFO - PID 6800 | 1639688468797 webdriver::server DEBUG Teardown session
[task 2021-12-16T21:01:08.802Z] 21:01:08 INFO - PID 6800 | JavaScript error: resource://gre/modules/URLQueryStrippingListService.jsm, line 90: TypeError: can't access property "removeEventListener", Services.cpmm.sharedData is null
[task 2021-12-16T21:01:08.804Z] 21:01:08 INFO - PID 6800 | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2021-12-16T21:01:08.805Z] 21:01:08 INFO - PID 6800 | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2021-12-16T21:01:08.806Z] 21:01:08 INFO - PID 6800 | 1639688468804 Marionette DEBUG Closed connection 0
[task 2021-12-16T21:01:08.880Z] 21:01:08 INFO - PID 6800 | JavaScript error: resource://gre/modules/URLQueryStrippingListService.jsm, line 90: TypeError: can't access property "removeEventListener", Services.cpmm.sharedData is null
[task 2021-12-16T21:01:08.880Z] 21:01:08 INFO - PID 6800 | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2021-12-16T21:01:08.880Z] 21:01:08 INFO - PID 6800 | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2021-12-16T21:01:09.212Z] 21:01:09 INFO - PID 6800 | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2021-12-16T21:01:10.127Z] 21:01:10 INFO - PID 6800 | Waiting in WillDestroyCurrentMessageLoop for pid 7380
[task 2021-12-16T21:01:27.873Z] 21:01:27 INFO - PID 6800 | Waiting in WillDestroyCurrentMessageLoop for pid 7788
[task 2021-12-16T21:01:27.884Z] 21:01:27 INFO - PID 6800 | Waiting in WillDestroyCurrentMessageLoop for pid 1788
[task 2021-12-16T21:01:27.885Z] 21:01:27 INFO - PID 6800 | Waiting in WillDestroyCurrentMessageLoop for pid 8452
[task 2021-12-16T21:01:27.886Z] 21:01:27 INFO - PID 6800 | Waiting in WillDestroyCurrentMessageLoop for pid 2396
[task 2021-12-16T21:01:47.318Z] 21:01:47 INFO - PID 6800 | 1639688507319 geckodriver::browser DEBUG Browser process stopped: exit code: 0
[task 2021-12-16T21:01:47.321Z] 21:01:47 INFO - PID 6800 | 1639688507320 webdriver::server DEBUG <- 200 OK {"value":null}
[task 2021-12-16T21:01:47.323Z] 21:01:47 INFO - PID 6800 | 1639688507321 webdriver::server DEBUG -> POST /session {"capabilities": {"alwaysMatch": {"moz:firefoxOptions": {"args": ["--profile", "C:\\Users\\task_163968445541348\\AppData\\Local\\Temp\\tmpbkcwsjt3.mozrunner"], "binary": "Z:\\task_163968445541348\\build\\application\\firefox\\firefox.exe"}}}}
[task 2021-12-16T21:01:47.324Z] 21:01:47 INFO - PID 6800 | 1639688507321 geckodriver::capabilities DEBUG Trying to read firefox version from ini files
[task 2021-12-16T21:01:47.325Z] 21:01:47 INFO - PID 6800 | 1639688507322 geckodriver::capabilities DEBUG Found version 97.0a1
[task 2021-12-16T21:01:47.334Z] 21:01:47 INFO - PID 6800 | 1639688507332 geckodriver::browser DEBUG Backing up prefs to "C:\\Users\\task_163968445541348\\AppData\\Local\\Temp\\tmpbkcwsjt3.mozrunner\\user.geckodriver_backup_11"
[task 2021-12-16T21:01:47.346Z] 21:01:47 INFO - PID 6800 | 1639688507347 mozrunner::runner INFO Running command: "Z:\\task_163968445541348\\build\\application\\firefox\\firefox.exe" "--marionette" "--profile" "C:\\Users\\task_163968445541348\\AppData\\Local\\Temp\\tmpbkcwsjt3.mozrunner" "-no-remote"
[task 2021-12-16T21:01:47.361Z] 21:01:47 INFO - PID 6800 | 1639688507360 geckodriver::marionette DEBUG Waiting 60s to connect to browser on 127.0.0.1:2828
[task 2021-12-16T21:01:47.734Z] 21:01:47 INFO - PID 6800 | 1639688507745 Marionette INFO Marionette enabled
[task 2021-12-16T21:01:49.401Z] 21:01:49 INFO - PID 6800 | 1639688509402 geckodriver::marionette TRACE No connection could be made because the target machine actively refused it. (os error 10061). Retrying in 100ms
[task 2021-12-16T21:01:49.803Z] 21:01:49 INFO - PID 6800 | 1639688509808 Marionette TRACE Received observer notification marionette-startup-requested
[task 2021-12-16T21:01:49.811Z] 21:01:49 INFO - PID 6800 | 1639688509809 Marionette TRACE Waiting until startup recorder finished recording startup scripts...
[task 2021-12-16T21:01:49.824Z] 21:01:49 INFO - PID 6800 | 1639688509835 Marionette TRACE All scripts recorded.
[task 2021-12-16T21:01:49.839Z] 21:01:49 INFO - PID 6800 | 1639688509837 Marionette INFO Listening on port 2828
[task 2021-12-16T21:01:49.840Z] 21:01:49 INFO - PID 6800 | 1639688509838 Marionette DEBUG Marionette is listening
[task 2021-12-16T21:01:50.003Z] 21:01:50 INFO - PID 6800 | 1639688510011 Marionette DEBUG Accepted connection 0 from 127.0.0.1:61276
[task 2021-12-16T21:01:50.014Z] 21:01:50 INFO - PID 6800 | 1639688510013 geckodriver::marionette DEBUG Connection to Marionette established on 127.0.0.1:2828.
[task 2021-12-16T21:01:50.018Z] 21:01:50 INFO - PID 6800 | 1639688510017 Marionette DEBUG 0 -> [0,1,"WebDriver:NewSession",{}]
[task 2021-12-16T21:01:50.032Z] 21:01:50 INFO - PID 6800 | 1639688510033 Marionette DEBUG 0 <- [1,1,null,{"sessionId":"51fd0a34-e773-4bcb-a1b1-8a6210046212","capabilities":{"browserName":"firefox","browserVersion":"97.0a ... 3.mozrunner","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true,"proxy":{}}}]
[task 2021-12-16T21:01:50.043Z] 21:01:50 INFO - PID 6800 | 1639688510038 webdriver::server DEBUG <- 200 OK {"value":{"sessionId":"51fd0a34-e773-4bcb-a1b1-8a6210046212","capabilities":{"acceptInsecureCerts":false,"browserName":"firefox","browserVersion":"97.0a1","moz:accessibilityChecks":false,"moz:buildID":"20211216163155","moz:geckodriverVersion":"0.30.0","moz:headless":false,"moz:processID":2748,"moz:profile":"C:\\Users\\task_163968445541348\\AppData\\Local\\Temp\\tmpbkcwsjt3.mozrunner","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true,"pageLoadStrategy":"normal","platformName":"windows","platformVersion":"10.0","proxy":{},"setWindowRect":true,"strictFileInteractability":false,"timeouts":{"implicit":0,"pageLoad":300000,"script":30000},"unhandledPromptBehavior":"dismiss and notify"}}}
[task 2021-12-16T21:01:50.044Z] 21:01:50 INFO - PID 6800 | 1639688510040 webdriver::server DEBUG -> POST /session/51fd0a34-e773-4bcb-a1b1-8a6210046212/window/rect {"width": 800, "height": 600}
[task 2021-12-16T21:01:50.045Z] 21:01:50 INFO - PID 6800 | 1639688510041 Marionette DEBUG 0 -> [0,2,"WebDriver:SetWindowRect",{"height":600,"width":800}]
[task 2021-12-16T21:01:50.046Z] 21:01:50 INFO - PID 6800 | 1639688510042 Marionette DEBUG 0 <- [1,2,null,{"x":100,"y":100,"width":800,"height":600}]
[task 2021-12-16T21:01:50.047Z] 21:01:50 INFO - PID 6800 | 1639688510043 webdriver::server DEBUG <- 200 OK {"value":{"x":100,"y":100,"width":800,"height":600}}
[task 2021-12-16T21:01:50.048Z] 21:01:50 INFO - PID 6800 | 1639688510044 webdriver::server DEBUG -> POST /session/51fd0a34-e773-4bcb-a1b1-8a6210046212/window/rect {"x": 100, "y": 100}
[task 2021-12-16T21:01:50.048Z] 21:01:50 INFO - PID 6800 | 1639688510045 Marionette DEBUG 0 -> [0,3,"WebDriver:SetWindowRect",{"x":100,"y":100}]
[task 2021-12-16T21:01:50.049Z] 21:01:50 INFO - PID 6800 | 1639688510046 Marionette DEBUG 0 <- [1,3,null,{"x":100,"y":100,"width":800,"height":600}]
[task 2021-12-16T21:01:50.050Z] 21:01:50 INFO - PID 6800 | 1639688510047 webdriver::server DEBUG <- 200 OK {"value":{"x":100,"y":100,"width":800,"height":600}}
[task 2021-12-16T21:01:50.051Z] 21:01:50 INFO - PID 6800 | 1639688510049 webdriver::server DEBUG -> POST /session/51fd0a34-e773-4bcb-a1b1-8a6210046212/execute/sync {"script": "return document.hidden", "args": []}
[task 2021-12-16T21:01:50.052Z] 21:01:50 INFO - PID 6800 | 1639688510050 Marionette DEBUG 0 -> [0,4,"WebDriver:ExecuteScript",{"args":[],"script":"return document.hidden"}]
[task 2021-12-16T21:01:50.060Z] 21:01:50 INFO - PID 6800 | 1639688510058 Marionette TRACE [32] MarionetteCommands actor created for window id 4294967297
[task 2021-12-16T21:01:50.069Z] 21:01:50 INFO - PID 6800 | 1639688510067 Marionette DEBUG 0 <- [1,4,null,{"value":false}]
[task 2021-12-16T21:01:50.070Z] 21:01:50 INFO - PID 6800 | 1639688510067 webdriver::server DEBUG <- 200 OK {"value":false}
[task 2021-12-16T21:01:50.156Z] 21:01:50 INFO - PID 6800 | 1639688510157 webdriver::server DEBUG -> POST /session/51fd0a34-e773-4bcb-a1b1-8a6210046212/execute/sync {"script": "return document.hidden", "args": []}
[task 2021-12-16T21:01:50.160Z] 21:01:50 INFO - PID 6800 | 1639688510158 Marionette DEBUG 0 -> [0,5,"WebDriver:ExecuteScript",{"args":[],"script":"return document.hidden"}]
[task 2021-12-16T21:01:50.164Z] 21:01:50 INFO - PID 6800 | 1639688510163 Marionette DEBUG 0 <- [1,5,null,{"value":false}]
[task 2021-12-16T21:01:50.165Z] 21:01:50 INFO - PID 6800 | 1639688510163 webdriver::server DEBUG <- 200 OK {"value":false}
[task 2021-12-16T21:01:50.272Z] 21:01:50 INFO - PID 6800 | 1639688510273 webdriver::server DEBUG -> POST /session/51fd0a34-e773-4bcb-a1b1-8a6210046212/execute/sync {"script": "return document.hidden", "args": []}
[task 2021-12-16T21:01:50.275Z] 21:01:50 INFO - PID 6800 | 1639688510275 Marionette DEBUG 0 -> [0,6,"WebDriver:ExecuteScript",{"args":[],"script":"return document.hidden"}]
[task 2021-12-16T21:01:50.279Z] 21:01:50 INFO - PID 6800 | 1639688510278 Marionette DEBUG 0 <- [1,6,null,{"value":false}]
[task 2021-12-16T21:01:50.280Z] 21:01:50 INFO - PID 6800 | 1639688510279 webdriver::server DEBUG <- 200 OK {"value":false}
[task 2021-12-16T21:01:50.388Z] 21:01:50 INFO - PID 6800 | 1639688510389 webdriver::server DEBUG -> POST /session/51fd0a34-e773-4bcb-a1b1-8a6210046212/execute/sync {"script": "return document.hidden", "args": []}
[task 2021-12-16T21:01:50.392Z] 21:01:50 INFO - PID 6800 | 1639688510390 Marionette DEBUG 0 -> [0,7,"WebDriver:ExecuteScript",{"args":[],"script":"return document.hidden"}]
[task 2021-12-16T21:01:50.395Z] 21:01:50 INFO - PID 6800 | 1639688510394 Marionette DEBUG 0 <- [1,7,null,{"value":false}]
[task 2021-12-16T21:01:50.396Z] 21:01:50 INFO - PID 6800 | 1639688510395 webdriver::server DEBUG <- 200 OK {"value":false}
[task 2021-12-16T21:01:50.503Z] 21:01:50 INFO - PID 6800 | 1639688510505 webdriver::server DEBUG -> POST /session/51fd0a34-e773-4bcb-a1b1-8a6210046212/execute/sync {"script": "return document.hidden", "args": []}
[task 2021-12-16T21:01:50.507Z] 21:01:50 INFO - PID 6800 | 1639688510506 Marionette DEBUG 0 -> [0,8,"WebDriver:ExecuteScript",{"args":[],"script":"return document.hidden"}]
[task 2021-12-16T21:01:50.512Z] 21:01:50 INFO - PID 6800 | 1639688510511 Marionette DEBUG 0 <- [1,8,null,{"value":false}]
[task 2021-12-16T21:01:50.513Z] 21:01:50 INFO - PID 6800 | 1639688510512 webdriver::server DEBUG <- 200 OK {"value":false}
[task 2021-12-16T21:01:50.605Z] 21:01:50 INFO - PID 6800 | 1639688510606 webdriver::server DEBUG -> POST /session/51fd0a34-e773-4bcb-a1b1-8a6210046212/execute/sync {"script": "return document.hidden", "args": []}
[task 2021-12-16T21:01:50.608Z] 21:01:50 INFO - PID 6800 | 1639688510607 Marionette DEBUG 0 -> [0,9,"WebDriver:ExecuteScript",{"args":[],"script":"return document.hidden"}]
[task 2021-12-16T21:01:50.612Z] 21:01:50 INFO - PID 6800 | 1639688510611 Marionette DEBUG 0 <- [1,9,null,{"value":false}]
[task 2021-12-16T21:01:50.613Z] 21:01:50 INFO - PID 6800 | 1639688510612 webdriver::server DEBUG <- 200 OK {"value":false}
[task 2021-12-16T21:01:50.720Z] 21:01:50 INFO - PID 6800 | 1639688510721 webdriver::server DEBUG -> POST /session/51fd0a34-e773-4bcb-a1b1-8a6210046212/execute/sync {"script": "return document.hidden", "args": []}
[task 2021-12-16T21:01:50.723Z] 21:01:50 INFO - PID 6800 | 1639688510722 Marionette DEBUG 0 -> [0,10,"WebDriver:ExecuteScript",{"args":[],"script":"return document.hidden"}]
[task 2021-12-16T21:01:50.729Z] 21:01:50 INFO - PID 6800 | 1639688510727 Marionette DEBUG 0 <- [1,10,null,{"value":false}]
[task 2021-12-16T21:01:50.729Z] 21:01:50 INFO - PID 6800 | 1639688510728 webdriver::server DEBUG <- 200 OK {"value":false}
[task 2021-12-16T21:01:50.842Z] 21:01:50 INFO - PID 6800 | 1639688510843 webdriver::server DEBUG -> POST /session/51fd0a34-e773-4bcb-a1b1-8a6210046212/execute/sync {"script": "return document.hidden", "args": []}
[task 2021-12-16T21:01:50.846Z] 21:01:50 INFO - PID 6800 | 1639688510845 Marionette DEBUG 0 -> [0,11,"WebDriver:ExecuteScript",{"args":[],"script":"return document.hidden"}]
[task 2021-12-16T21:01:50.851Z] 21:01:50 INFO - PID 6800 | 1639688510850 Marionette DEBUG 0 <- [1,11,null,{"value":false}]
[task 2021-12-16T21:01:50.851Z] 21:01:50 INFO - PID 6800 | 1639688510850 webdriver::server DEBUG <- 200 OK {"value":false}
[task 2021-12-16T21:01:50.958Z] 21:01:50 INFO - PID 6800 | 1639688510959 webdriver::server DEBUG -> POST /session/51fd0a34-e773-4bcb-a1b1-8a6210046212/execute/sync {"script": "return document.hidden", "args": []}
[task 2021-12-16T21:01:50.961Z] 21:01:50 INFO - PID 6800 | 1639688510960 Marionette DEBUG 0 -> [0,12,"WebDriver:ExecuteScript",{"args":[],"script":"return document.hidden"}]
[task 2021-12-16T21:01:50.965Z] 21:01:50 INFO - PID 6800 | 1639688510964 Marionette DEBUG 0 <- [1,12,null,{"value":false}]
[task 2021-12-16T21:01:50.966Z] 21:01:50 INFO - PID 6800 | 1639688510965 webdriver::server DEBUG <- 200 OK {"value":false}
[task 2021-12-16T21:01:51.074Z] 21:01:51 INFO - PID 6800 | 1639688511075 webdriver::server DEBUG -> POST /session/51fd0a34-e773-4bcb-a1b1-8a6210046212/execute/sync {"script": "return document.hidden", "args": []}
[task 2021-12-16T21:01:51.077Z] 21:01:51 INFO - PID 6800 | 1639688511076 Marionette DEBUG 0 -> [0,13,"WebDriver:ExecuteScript",{"args":[],"script":"return document.hidden"}]
[task 2021-12-16T21:01:51.081Z] 21:01:51 INFO - PID 6800 | 1639688511080 Marionette DEBUG 0 <- [1,13,null,{"value":false}]
[task 2021-12-16T21:01:51.082Z] 21:01:51 INFO - PID 6800 | 1639688511080 webdriver::server DEBUG <- 200 OK {"value":false}
[task 2021-12-16T21:01:51.190Z] 21:01:51 INFO - PID 6800 | 1639688511191 webdriver::server DEBUG -> POST /session/51fd0a34-e773-4bcb-a1b1-8a6210046212/execute/sync {"script": "return document.hidden", "args": []}
[task 2021-12-16T21:01:51.193Z] 21:01:51 INFO - PID 6800 | 1639688511192 Marionette DEBUG 0 -> [0,14,"WebDriver:ExecuteScript",{"args":[],"script":"return document.hidden"}]
[task 2021-12-16T21:01:51.198Z] 21:01:51 INFO - PID 6800 | 1639688511196 Marionette DEBUG 0 <- [1,14,null,{"value":false}]
[task 2021-12-16T21:01:51.198Z] 21:01:51 INFO - PID 6800 | 1639688511197 webdriver::server DEBUG <- 200 OK {"value":false}
[task 2021-12-16T21:01:51.312Z] 21:01:51 INFO - PID 6800 | 1639688511311 webdriver::server DEBUG -> POST /session/51fd0a34-e773-4bcb-a1b1-8a6210046212/execute/sync {"script": "return document.hidden", "args": []}
[task 2021-12-16T21:01:51.315Z] 21:01:51 INFO - PID 6800 | 1639688511312 Marionette DEBUG 0 -> [0,15,"WebDriver:ExecuteScript",{"args":[],"script":"return document.hidden"}]
[task 2021-12-16T21:01:51.319Z] 21:01:51 INFO - PID 6800 | 1639688511318 Marionette DEBUG 0 <- [1,15,null,{"value":false}]
[task 2021-12-16T21:01:51.320Z] 21:01:51 INFO - PID 6800 | 1639688511318 webdriver::server DEBUG <- 200 OK {"value":false}
[task 2021-12-16T21:01:51.414Z] 21:01:51 INFO - PID 6800 | 1639688511413 webdriver::server DEBUG -> POST /session/51fd0a34-e773-4bcb-a1b1-8a6210046212/execute/sync {"script": "return document.hidden", "args": []}
[task 2021-12-16T21:01:51.415Z] 21:01:51 INFO - PID 6800 | 1639688511414 Marionette DEBUG 0 -> [0,16,"WebDriver:ExecuteScript",{"args":[],"script":"return document.hidden"}]
[task 2021-12-16T21:01:51.419Z] 21:01:51 INFO - PID 6800 | 1639688511418 Marionette DEBUG 0 <- [1,16,null,{"value":false}]
[task 2021-12-16T21:01:51.420Z] 21:01:51 INFO - PID 6800 | 1639688511419 webdriver::server DEBUG <- 200 OK {"value":false}
[task 2021-12-16T21:01:51.516Z] 21:01:51 INFO - PID 6800 | 1639688511515 webdriver::server DEBUG -> POST /session/51fd0a34-e773-4bcb-a1b1-8a6210046212/execute/sync {"script": "return document.hidden", "args": []}
[task 2021-12-16T21:01:51.517Z] 21:01:51 INFO - PID 6800 | 1639688511516 Marionette DEBUG 0 -> [0,17,"WebDriver:ExecuteScript",{"args":[],"script":"return document.hidden"}]
[task 2021-12-16T21:01:51.528Z] 21:01:51 INFO - PID 6800 | 1639688511527 Marionette DEBUG 0 <- [1,17,null,{"value":false}]
[task 2021-12-16T21:01:51.529Z] 21:01:51 INFO - PID 6800 | 1639688511527 webdriver::server DEBUG <- 200 OK {"value":false}
[task 2021-12-16T21:01:51.628Z] 21:01:51 INFO - PID 6800 | 1639688511627 webdriver::server DEBUG -> POST /session/51fd0a34-e773-4bcb-a1b1-8a6210046212/execute/sync {"script": "return document.hidden", "args": []}
[task 2021-12-16T21:01:51.629Z] 21:01:51 INFO - PID 6800 | 1639688511628 Marionette DEBUG 0 -> [0,18,"WebDriver:ExecuteScript",{"args":[],"script":"return document.hidden"}]
[task 2021-12-16T21:01:51.634Z] 21:01:51 INFO - PID 6800 | 1639688511632 Marionette DEBUG 0 <- [1,18,null,{"value":false}]
[task 2021-12-16T21:01:51.635Z] 21:01:51 INFO - PID 6800 | 1639688511632 webdriver::server DEBUG <- 200 OK {"value":false}
[task 2021-12-16T21:01:51.729Z] 21:01:51 INFO - PID 6800 | 1639688511728 webdriver::server DEBUG -> POST /session/51fd0a34-e773-4bcb-a1b1-8a6210046212/execute/sync {"script": "return document.hidden", "args": []}
[task 2021-12-16T21:01:51.731Z] 21:01:51 INFO - PID 6800 | 1639688511729 Marionette DEBUG 0 -> [0,19,"WebDriver:ExecuteScript",{"args":[],"script":"return document.hidden"}]
[task 2021-12-16T21:01:51.736Z] 21:01:51 INFO - PID 6800 | 1639688511733 Marionette DEBUG 0 <- [1,19,null,{"value":false}]
[task 2021-12-16T21:01:51.737Z] 21:01:51 INFO - PID 6800 | 1639688511734 webdriver::server DEBUG <- 200 OK {"value":false}
[task 2021-12-16T21:01:51.831Z] 21:01:51 INFO - PID 6800 | 1639688511830 webdriver::server DEBUG -> POST /session/51fd0a34-e773-4bcb-a1b1-8a6210046212/execute/sync {"script": "return document.hidden", "args": []}
[task 2021-12-16T21:01:51.833Z] 21:01:51 INFO - PID 6800 | 1639688511831 Marionette DEBUG 0 -> [0,20,"WebDriver:ExecuteScript",{"args":[],"script":"return document.hidden"}]
[task 2021-12-16T21:01:51.837Z] 21:01:51 INFO - PID 6800 | 1639688511837 Marionette DEBUG 0 <- [1,20,null,{"value":false}]
[task 2021-12-16T21:01:51.838Z] 21:01:51 INFO - PID 6800 | 1639688511837 webdriver::server DEBUG <- 200 OK {"value":false}
[task 2021-12-16T21:01:51.933Z] 21:01:51 INFO - PID 6800 | 1639688511932 webdriver::server DEBUG -> POST /session/51fd0a34-e773-4bcb-a1b1-8a6210046212/execute/sync {"script": "return document.hidden", "args": []}
[task 2021-12-16T21:01:51.934Z] 21:01:51 INFO - PID 6800 | 1639688511933 Marionette DEBUG 0 -> [0,21,"WebDriver:ExecuteScript",{"args":[],"script":"return document.hidden"}]
[task 2021-12-16T21:01:51.939Z] 21:01:51 INFO - PID 6800 | 1639688511938 Marionette DEBUG 0 <- [1,21,null,{"value":false}]
[task 2021-12-16T21:01:51.940Z] 21:01:51 INFO - PID 6800 | 1639688511938 webdriver::server DEBUG <- 200 OK {"value":false}
[task 2021-12-16T21:01:52.035Z] 21:01:52 INFO - PID 6800 | 1639688512035 webdriver::server DEBUG -> POST /session/51fd0a34-e773-4bcb-a1b1-8a6210046212/execute/sync {"script": "return document.hidden", "args": []}
[task 2021-12-16T21:01:52.039Z] 21:01:52 INFO - PID 6800 | 1639688512036 Marionette DEBUG 0 -> [0,22,"WebDriver:ExecuteScript",{"args":[],"script":"return document.hidden"}]
[task 2021-12-16T21:01:52.042Z] 21:01:52 INFO - PID 6800 | 1639688512041 Marionette DEBUG 0 <- [1,22,null,{"value":false}]
[task 2021-12-16T21:01:52.043Z] 21:01:52 INFO - PID 6800 | 1639688512041 webdriver::server DEBUG <- 200 OK {"value":false}
[task 2021-12-16T21:01:52.118Z] 21:01:52 INFO - TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/minimize_window/user_prompts.py | expected OK
[task 2021-12-16T21:01:52.118Z] 21:01:52 INFO - TEST-INFO took 365012ms
[task 2021-12-16T21:01:52.120Z] 21:01:52 INFO - Restarting browser for new test group
[task 2021-12-16T21:01:56.593Z] 21:01:56 INFO - Closing logging queue
[task 2021-12-16T21:01:56.605Z] 21:01:56 INFO - queue closed
[task 2021-12-16T21:01:56.609Z] 21:01:56 INFO - Starting runner
[task 2021-12-16T21:01:58.045Z] 21:01:58 INFO - PID 8736 | 1639688517539 geckodriver INFO Listening on 127.0.0.1:61303
[task 2021-12-16T21:01:58.048Z] 21:01:58 INFO - WebDriver HTTP server listening at http://127.0.0.1:61303/
[task 2021-12-16T21:01:58.050Z] 21:01:58 INFO - TEST-START | /webdriver/tests/perform_actions/key.py
|
||
Comment 1•3 years ago
|
||
There is a delay during the shutdown of Firefox which seems to be related to the attempt in trying to destroy the current message loop for each of the processes:
[task 2021-12-16T21:01:08.880Z] 21:01:08 INFO - PID 6800 | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2021-12-16T21:01:09.212Z] 21:01:09 INFO - PID 6800 | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2021-12-16T21:01:10.127Z] 21:01:10 INFO - PID 6800 | Waiting in WillDestroyCurrentMessageLoop for pid 7380
[task 2021-12-16T21:01:27.873Z] 21:01:27 INFO - PID 6800 | Waiting in WillDestroyCurrentMessageLoop for pid 7788
[task 2021-12-16T21:01:27.884Z] 21:01:27 INFO - PID 6800 | Waiting in WillDestroyCurrentMessageLoop for pid 1788
[task 2021-12-16T21:01:27.885Z] 21:01:27 INFO - PID 6800 | Waiting in WillDestroyCurrentMessageLoop for pid 8452
[task 2021-12-16T21:01:27.886Z] 21:01:27 INFO - PID 6800 | Waiting in WillDestroyCurrentMessageLoop for pid 2396
[task 2021-12-16T21:01:47.318Z] 21:01:47 INFO - PID 6800 | 1639688507319 geckodriver::browser DEBUG Browser process stopped: exit code: 0
This takes up around 40s before Firefox has finally exited.
Component: geckodriver → IPC
Product: Testing → Core
|
|
||
Comment 2•3 years ago
|
||
Actually lets move back to geckodriver, and get a new bug filed for that particular problem if that's something new. jld, are you aware of that issue already?
Component: IPC → geckodriver
Flags: needinfo?(jld)
Product: Core → Testing
|
||
Comment 3•3 years ago
|
||
Hanging in WillDestroyCurrentMessageLoop is an issue we've seen intermittently on TreeHerder in various Mochitests, but I don't think anybody has managed to figure out what the issue is. That was usually manifesting as a hang in a single process, not a bunch of them, so maybe there's something else happening here.
| Comment hidden (Intermittent Failures Robot) |
|
|
||
Comment 5•3 years ago
|
||
Marking as incomplete given that no more failure happened since Dec 16th.
|
||
Comment 6•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
•