Closed Bug 1779600 Opened 2 years ago Closed 2 years ago

Intermittent TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/execute_async_script/user_prompts.py | expected OK

Categories

(Remote Protocol :: Marionette, defect, P5)

defect

Tracking

(Not tracked)

RESOLVED DUPLICATE of bug 1737282

People

(Reporter: intermittent-bug-filer, Unassigned)

Details

(Keywords: intermittent-failure)

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


[task 2022-07-14T16:01:29.501Z] 16:01:29     INFO - PID 1519 | console.error: BackgroundUpdate:
[task 2022-07-14T16:01:29.502Z] 16:01:29     INFO - PID 1519 |   _reasonsToNotScheduleUpdates: Failed to check for Maintenance Service Registry Key: [Exception... "Component returned failure code: 0x80004001 (NS_ERROR_NOT_IMPLEMENTED) [nsIUpdateProcessor.getServiceRegKeyExists]"  nsresult: "0x80004001 (NS_ERROR_NOT_IMPLEMENTED)"  location: "JS frame :: resource://gre/modules/BackgroundUpdate.jsm :: _reasonsToNotScheduleUpdates :: line 243"  data: no]
[task 2022-07-14T16:01:29.503Z] 16:01:29     INFO - PID 1519 | 1657814489502	Marionette	TRACE	All scripts recorded.
[task 2022-07-14T16:01:29.504Z] 16:01:29     INFO - PID 1519 | 1657814489503	Marionette	INFO	Listening on port 2828
[task 2022-07-14T16:01:29.505Z] 16:01:29     INFO - PID 1519 | 1657814489504	Marionette	DEBUG	Marionette is listening
[task 2022-07-14T16:01:29.509Z] 16:01:29     INFO - PID 1519 | 1657814489508	Marionette	DEBUG	Accepted connection 0 from 127.0.0.1:53501
[task 2022-07-14T16:01:29.510Z] 16:01:29     INFO - PID 1519 | 1657814489508	geckodriver::marionette	DEBUG	Connection to Marionette established on 127.0.0.1:2828.
[task 2022-07-14T16:01:29.511Z] 16:01:29     INFO - PID 1519 | 1657814489510	Marionette	DEBUG	0 -> [0,1,"WebDriver:NewSession",{}]
[task 2022-07-14T16:01:29.517Z] 16:01:29     INFO - PID 1519 | 1657814489515	Marionette	DEBUG	0 <- [1,1,null,{"sessionId":"44b5512f-2083-c448-b416-31f727ee853d","capabilities":{"browserName":"firefox","browserVersion":"91.12 ... 4.mozrunner","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true,"proxy":{}}}]
[task 2022-07-14T16:01:29.520Z] 16:01:29     INFO - PID 1519 | 1657814489516	webdriver::server	DEBUG	<- 200 OK {"value":{"sessionId":"44b5512f-2083-c448-b416-31f727ee853d","capabilities":{"acceptInsecureCerts":false,"browserName":"firefox","browserVersion":"91.12.0","moz:accessibilityChecks":false,"moz:buildID":"20220714125707","moz:geckodriverVersion":"0.29.1","moz:headless":false,"moz:processID":1550,"moz:profile":"/var/folders/6g/n83qhpfd3nl1tkncq9dmn5mm000014/T/tmp8w2w_pk4.mozrunner","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true,"pageLoadStrategy":"normal","platformName":"mac","platformVersion":"19.6.0","proxy":{},"setWindowRect":true,"strictFileInteractability":false,"timeouts":{"implicit":0,"pageLoad":300000,"script":30000},"unhandledPromptBehavior":"dismiss and notify"}}}
[task 2022-07-14T16:01:29.521Z] 16:01:29     INFO - PID 1519 | 1657814489517	webdriver::server	DEBUG	-> POST /session/44b5512f-2083-c448-b416-31f727ee853d/window/rect {"width": 800, "height": 600}
[task 2022-07-14T16:01:29.522Z] 16:01:29     INFO - PID 1519 | 1657814489517	Marionette	DEBUG	0 -> [0,2,"WebDriver:SetWindowRect",{"height":600,"width":800}]
[task 2022-07-14T16:01:29.523Z] 16:01:29     INFO - PID 1519 | 1657814489518	Marionette	TRACE	Requested window geometry matches
[task 2022-07-14T16:01:29.523Z] 16:01:29     INFO - PID 1519 | 1657814489518	Marionette	DEBUG	0 <- [1,2,null,{"x":100,"y":100,"width":800,"height":600}]
[task 2022-07-14T16:01:29.524Z] 16:01:29     INFO - PID 1519 | 1657814489518	webdriver::server	DEBUG	<- 200 OK {"value":{"x":100,"y":100,"width":800,"height":600}}
[task 2022-07-14T16:01:29.525Z] 16:01:29     INFO - PID 1519 | 1657814489519	webdriver::server	DEBUG	-> POST /session/44b5512f-2083-c448-b416-31f727ee853d/window/rect {"x": 100, "y": 100}
[task 2022-07-14T16:01:29.526Z] 16:01:29     INFO - PID 1519 | 1657814489520	Marionette	DEBUG	0 -> [0,3,"WebDriver:SetWindowRect",{"x":100,"y":100}]
[task 2022-07-14T16:01:29.527Z] 16:01:29     INFO - PID 1519 | 1657814489520	Marionette	TRACE	Requested window geometry matches
[task 2022-07-14T16:01:29.528Z] 16:01:29     INFO - PID 1519 | 1657814489520	Marionette	DEBUG	0 <- [1,3,null,{"x":100,"y":100,"width":800,"height":600}]
[task 2022-07-14T16:01:29.528Z] 16:01:29     INFO - PID 1519 | 1657814489520	webdriver::server	DEBUG	<- 200 OK {"value":{"x":100,"y":100,"width":800,"height":600}}
[task 2022-07-14T16:01:29.530Z] 16:01:29     INFO - PID 1519 | 1657814489522	webdriver::server	DEBUG	-> POST /session/44b5512f-2083-c448-b416-31f727ee853d/execute/async {"script": "\n            let dialog_type = arguments[0];\n            let text = arguments[1];\n\n            setTimeout(function() {\n              if (dialog_type == 'prompt') {\n                window.dialog_return_value = window[dialog_type](text, '');\n              } else {\n                window.dialog_return_value = window[dialog_type](text);\n              }\n            }, 0);\n            ", "args": ["alert", "alert"]}
[task 2022-07-14T16:01:29.530Z] 16:01:29     INFO - PID 1519 | 1657814489522	Marionette	DEBUG	0 -> [0,4,"WebDriver:ExecuteAsyncScript",{"args":["alert","alert"],"script":"\n            let dialog_type = arguments[0];\n       ...                 window.dialog_return_value = window[dialog_type](text);\n              }\n            }, 0);\n            "}]
[task 2022-07-14T16:01:29.543Z] 16:01:29     INFO - PID 1519 | DEBUG: Adding blocker DownloadAutoSaveView: writing data for phase profile-before-change
[task 2022-07-14T16:01:29.592Z] 16:01:29     INFO - PID 1519 | DEBUG: Adding blocker content-prefs.sqlite#0: waiting for shutdown for phase Sqlite.jsm: wait until all connections are closed
[task 2022-07-14T16:01:29.593Z] 16:01:29     INFO - PID 1519 | DEBUG: Adding blocker Closing ContentPrefService2 connection. for phase Sqlite.jsm: wait until all clients have completed their task
[task 2022-07-14T16:01:29.593Z] 16:01:29     INFO - PID 1519 | DEBUG: Adding blocker ScriptPreloader: Saving bytecode cache for phase xpcom-will-shutdown
[task 2022-07-14T16:01:29.594Z] 16:01:29     INFO - PID 1519 | DEBUG: Adding blocker Transaction (0) for phase content-prefs.sqlite#0: waiting for clients
[task 2022-07-14T16:01:29.595Z] 16:01:29     INFO - PID 1519 | DEBUG: Completed blocker Transaction (0) for phase content-prefs.sqlite#0: waiting for clients
[task 2022-07-14T16:01:29.596Z] 16:01:29     INFO - PID 1519 | 1657814489592	Marionette	TRACE	[29] MarionetteCommands actor created for window id 6
[task 2022-07-14T16:01:29.601Z] 16:01:29     INFO - PID 1519 | 1657814489599	Marionette	TRACE	[29] MarionetteEvents actor created for window id 6
[task 2022-07-14T16:01:29.611Z] 16:01:29     INFO - PID 1519 | JavaScript error: resource://gre/actors/BrowserElementChild.jsm, line 22: TypeError: this.contentWindow is null
[task 2022-07-14T16:01:29.612Z] 16:01:29     INFO - PID 1519 | 1657814489611	Marionette	TRACE	[29] MarionetteEvents actor created for window id 2147483649
[task 2022-07-14T16:01:29.618Z] 16:01:29     INFO - PID 1519 | 1657814489616	Marionette	DEBUG	0 <- [1,4,{"error":"javascript error","message":"JavaScriptError: Document was unloaded","stacktrace":"WebDriverError@chrome://rem ... nalert@resource://gre/modules/Prompter.jsm:1394:17\n@moz-nullprincipal:{f29c0d6f-7199-417b-a1b4-ec3098adfc1f}:10:65\n"},null]
[task 2022-07-14T16:01:29.620Z] 16:01:29     INFO - PID 1519 | JavaScript error: moz-nullprincipal:{f29c0d6f-7199-417b-a1b4-ec3098adfc1f}, line 10: SecurityError: Permission denied to access property "dialog_return_value" on cross-origin object
[task 2022-07-14T16:01:29.620Z] 16:01:29     INFO - PID 1519 | JavaScript error: resource://gre/modules/Prompter.jsm, line 1117: AbortError: Actor 'Prompt' destroyed before query 'Prompt:Open' was resolved
[task 2022-07-14T16:01:29.630Z] 16:01:29     INFO - PID 1519 | 1657814489623	webdriver::server	DEBUG	<- 500 Internal Server Error {"value":{"error":"javascript error","message":"JavaScriptError: Document was unloaded","stacktrace":"WebDriverError@chrome://remote/content/shared/webdriver/Errors.jsm:181:5\nJavaScriptError@chrome://remote/content/shared/webdriver/Errors.jsm:360:5\nevaluate.sandbox/promise</unloadHandler<@chrome://remote/content/marionette/evaluate.js:132:20\nopenPromptSync@resource://gre/modules/Prompter.jsm:1117:17\nalert@resource://gre/modules/Prompter.jsm:1394:17\n@moz-nullprincipal:{f29c0d6f-7199-417b-a1b4-ec3098adfc1f}:10:65\n"}}
[task 2022-07-14T16:01:29.634Z] 16:01:29     INFO - PID 1519 | 1657814489623	Marionette	TRACE	Received event DOMModalDialogClosed
[task 2022-07-14T16:01:29.665Z] 16:01:29     INFO - STDOUT: FAILED
[task 2022-07-14T16:01:29.666Z] 16:01:29     INFO - PID 1519 | 1657814489664	webdriver::server	DEBUG	-> POST /session/44b5512f-2083-c448-b416-31f727ee853d/timeouts {"implicit": 0}
[task 2022-07-14T16:04:22.540Z] 16:04:22     INFO - TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/execute_async_script/user_prompts.py | expected OK
[task 2022-07-14T16:04:22.540Z] 16:04:22     INFO - TEST-INFO took 185137ms
Status: NEW → RESOLVED
Closed: 2 years ago
Resolution: --- → DUPLICATE

This is a dupe of bug 1737282 and only happens on the esr91 branch.

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.