1606637 - Prevent Sleep() from logging "TimedPromise timed out after 5000 ms"

Assignee

Description

•

4 years ago

Currently Sleep() uses the TimedPromise and as such outputs the following warning with an additional stack each time when it has been used:

TimedPromise timed out after 5000 ms

It would be good if we could just make it use of a Promise directly, and avoid this useless logging output.

I already tried that a couple months ago but it failed webdriver tests. See my patch on https://phabricator.services.mozilla.com/D20638.

Henrik Skupin [:whimboo][⌚️UTC+1]

Assignee

Comment 1

•

4 years ago

This is actually an annoyance factor when looking at the Marionette logs, and also lot of people complain about this warning and get the impression that it is the problem why some commands aren't working as expected. It will be good to just get this fixed. I will try it once more.

Assignee: nobody → hskupin

Status: NEW → ASSIGNED

Priority: P3 → P1

Henrik Skupin [:whimboo][⌚️UTC+1]

Assignee

Comment 2

•

4 years ago

Attached file Bug 1606637 - [marionette] Use plain Promise instead of TimedPromise for Sleep. — Details

TimedPromise logs a warning if the timeout exceeded and not error
should be raised. Given that Sleep always runs into that condition
a lot of inappropriate log entries are made that also causes
confusion for our users when commands (especially actions) don't
work as expected.

Henrik Skupin [:whimboo][⌚️UTC+1]

Assignee

Comment 3

•

4 years ago

I would like to see this fixed for Firefox 81.

status-firefox80: --- → wontfix

status-firefox81: --- → affected

status-firefox82: --- → affected

Henrik Skupin [:whimboo][⌚️UTC+1]

Assignee

Updated

•

4 years ago

URL: https://github.com/mozilla/geckodrive...

Marco Mucci [:MarcoM]

Comment 4

•

4 years ago

Hi Henrik. Does this bug need to be included in the Marionette MVP?

Flags: needinfo?(hskupin)

Henrik Skupin [:whimboo][⌚️UTC+1]

Assignee

Comment 5

•

4 years ago

(In reply to Marco Mucci [:MarcoM] from comment #4)

Hi Henrik. Does this bug need to be included in the Marionette MVP?

No.

Flags: needinfo?(hskupin)

Pulsebot

Comment 6

•

4 years ago

Pushed by hskupin@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/cb50aecf4bad
[marionette] Use plain Promise instead of TimedPromise for Sleep. r=marionette-reviewers,maja_zf

Pulsebot

Comment 7

•

4 years ago

Backout by btara@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/995e86e7ea4e
Backed out changeset cb50aecf4bad for perform_actions/pointer* failures CLOSED TREE

Bogdan Tara[:bogdan_tara | bogdant]

Comment 8

•

4 years ago

Backed out changeset cb50aecf4bad (bug 1606637) for perform_actions/pointer* failures.

Push with failures: https://treeherder.mozilla.org/#/jobs?repo=autoland&group_state=expanded&searchStr=linux%2C18.04%2Cx64%2Cwebrender%2Copt%2Cweb%2Cplatform%2Ctests%2Cwith%2Cfission%2Cenabled%2Ctest-linux1804-64-qr%2Fopt-web-platform-tests-wdspec-fis-e10s%2Cwd2&fromchange=5ae3f7011ba21ab9ccf79999b7cdab9f18648d7e&selectedTaskRun=XiW2_eKwT9mzoPyX4NPFwA.0&tochange=190ed8e734b291a1c4932fe2c99514b4b3f8dacf

Backout link: https://hg.mozilla.org/integration/autoland/rev/995e86e7ea4e9356df1bb209948610ac962dfa3f

Failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=315169910&repo=autoland&lineNumber=106877

[task 2020-09-09T01:37:33.933Z] 01:37:33     INFO - TEST-START | /webdriver/tests/perform_actions/pointer_pause_dblclick.py
[task 2020-09-09T01:37:33.954Z] 01:37:33     INFO - STDOUT: ============================= test session starts ==============================
[task 2020-09-09T01:37:33.954Z] 01:37:33     INFO - STDOUT: platform linux2 -- Python 2.7.17, pytest-unknown, py-1.5.2, pluggy-0.5.3.dev -- /builds/worker/workspace/build/venv/bin/python
[task 2020-09-09T01:37:33.954Z] 01:37:33     INFO - STDOUT: rootdir: /builds/worker/workspace/build, inifile:
[task 2020-09-09T01:37:33.955Z] 01:37:33     INFO - STDOUT: collecting ... 
[task 2020-09-09T01:37:33.962Z] 01:37:33     INFO - STDOUT: collected 2 items
[task 2020-09-09T01:37:33.962Z] 01:37:33     INFO - STDOUT: tests/web-platform/tests/webdriver/tests/perform_actions/pointer_pause_dblclick.py::test_dblclick_with_pause_after_second_pointerdown 
[task 2020-09-09T01:37:33.970Z] 01:37:33     INFO - PID 14622 | 1599615453960	webdriver::server	DEBUG	-> POST /session/00d98fb5-3827-49cf-ba98-e57ef969ed76/window/rect {"width": 800, "height": 600}
[task 2020-09-09T01:37:33.970Z] 01:37:33     INFO - PID 14622 | 1599615453960	Marionette	DEBUG	0 -> [0,3927,"WebDriver:SetWindowRect",{"height":600,"width":800}]
[task 2020-09-09T01:37:33.971Z] 01:37:33     INFO - PID 14622 | 1599615453961	Marionette	DEBUG	0 <- [1,3927,null,{"x":100,"y":100,"width":800,"height":600}]
[task 2020-09-09T01:37:33.971Z] 01:37:33     INFO - PID 14622 | 1599615453961	webdriver::server	DEBUG	<- 200 OK {"value":{"x":100,"y":100,"width":800,"height":600}}
[task 2020-09-09T01:37:33.971Z] 01:37:33     INFO - PID 14622 | 1599615453962	webdriver::server	DEBUG	-> POST /session/00d98fb5-3827-49cf-ba98-e57ef969ed76/window/rect {"y": 100, "x": 100}
[task 2020-09-09T01:37:33.972Z] 01:37:33     INFO - PID 14622 | 1599615453963	Marionette	DEBUG	0 -> [0,3928,"WebDriver:SetWindowRect",{"x":100,"y":100}]
[task 2020-09-09T01:37:33.972Z] 01:37:33     INFO - PID 14622 | 1599615453964	Marionette	DEBUG	0 <- [1,3928,null,{"x":100,"y":100,"width":800,"height":600}]
[task 2020-09-09T01:37:33.973Z] 01:37:33     INFO - PID 14622 | 1599615453964	webdriver::server	DEBUG	<- 200 OK {"value":{"x":100,"y":100,"width":800,"height":600}}
[task 2020-09-09T01:37:33.974Z] 01:37:33     INFO - PID 14622 | 1599615453965	webdriver::server	DEBUG	-> POST /session/00d98fb5-3827-49cf-ba98-e57ef969ed76/url {"url": "http://web-platform.test:8000/webdriver/tests/perform_actions/support/test_actions_wdspec.html"}
[task 2020-09-09T01:37:33.974Z] 01:37:33     INFO - PID 14622 | 1599615453966	Marionette	DEBUG	0 -> [0,3929,"WebDriver:Navigate",{"url":"http://web-platform.test:8000/webdriver/tests/perform_actions/support/test_actions_wdspec.html"}]
[task 2020-09-09T01:37:33.975Z] 01:37:33     INFO - PID 14622 | 1599615453966	Marionette	TRACE	Using browsing context 17
[task 2020-09-09T01:37:33.976Z] 01:37:33     INFO - PID 14622 | 1599615453968	Marionette	TRACE	[17] Received DOM event beforeunload for http://web-platform.test:8000/webdriver/tests/support/inline.py?doc=%3C%21doctype+html%3E%0A%3Cmeta+charset%3DUTF-8%3E%0A%0A+ ... A+relative%3B+left%3A+-200px%3B+top%3A+-100px%3B%22%3E%3C%2Fdiv%3E%0A++++++%3C%2Fdiv%3E%0A++++&charset=UTF-8&mime=text%2Fhtml
[task 2020-09-09T01:37:33.979Z] 01:37:33     INFO - PID 14622 | 1599615453977	Marionette	TRACE	[17] Received DOM event pagehide for http://web-platform.test:8000/webdriver/tests/support/inline.py?doc=%3C%21doctype+html%3E%0A%3Cmeta+charset%3DUTF-8%3E%0A%0A+ ... A+relative%3B+left%3A+-200px%3B+top%3A+-100px%3B%22%3E%3C%2Fdiv%3E%0A++++++%3C%2Fdiv%3E%0A++++&charset=UTF-8&mime=text%2Fhtml
[task 2020-09-09T01:37:33.986Z] 01:37:33     INFO - PID 14622 | 1599615453983	Marionette	TRACE	[17] Received DOM event DOMContentLoaded for http://web-platform.test:8000/webdriver/tests/perform_actions/support/test_actions_wdspec.html
[task 2020-09-09T01:37:34.004Z] 01:37:34     INFO - PID 14622 | 1599615453993	Marionette	TRACE	[17] Received DOM event pageshow for http://web-platform.test:8000/webdriver/tests/perform_actions/support/test_actions_wdspec.html
[task 2020-09-09T01:37:34.005Z] 01:37:34     INFO - PID 14622 | 1599615453993	Marionette	DEBUG	0 <- [1,3929,null,{"value":null}]
[task 2020-09-09T01:37:34.005Z] 01:37:34     INFO - PID 14622 | 1599615453994	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2020-09-09T01:37:34.005Z] 01:37:34     INFO - PID 14622 | 1599615453995	webdriver::server	DEBUG	-> POST /session/00d98fb5-3827-49cf-ba98-e57ef969ed76/element {"using": "css selector", "value": "#outer"}
[task 2020-09-09T01:37:34.006Z] 01:37:34     INFO - PID 14622 | 1599615453996	Marionette	DEBUG	0 -> [0,3930,"WebDriver:FindElement",{"using":"css selector","value":"#outer"}]
[task 2020-09-09T01:37:34.006Z] 01:37:34     INFO - PID 14622 | 1599615454000	Marionette	DEBUG	0 <- [1,3930,null,{"value":{"element-6066-11e4-a52e-4f735466cecf":"4823b13a-85f2-4cdc-bba2-a1b7a91fba59"}}]
[task 2020-09-09T01:37:34.007Z] 01:37:34     INFO - PID 14622 | 1599615454000	webdriver::server	DEBUG	<- 200 OK {"value":{"element-6066-11e4-a52e-4f735466cecf":"4823b13a-85f2-4cdc-bba2-a1b7a91fba59"}}
[task 2020-09-09T01:37:34.007Z] 01:37:34     INFO - PID 14622 | 1599615454001	webdriver::server	DEBUG	-> GET /session/00d98fb5-3827-49cf-ba98-e57ef969ed76/element/4823b13a-85f2-4cdc-bba2-a1b7a91fba59/rect
[task 2020-09-09T01:37:34.011Z] 01:37:34     INFO - PID 14622 | 1599615454006	Marionette	DEBUG	0 -> [0,3931,"WebDriver:GetElementRect",{"id":"4823b13a-85f2-4cdc-bba2-a1b7a91fba59"}]
[task 2020-09-09T01:37:34.011Z] 01:37:34     INFO - PID 14622 | 1599615454008	Marionette	DEBUG	0 <- [1,3931,null,{"x":8,"y":166.6666717529297,"width":100,"height":50}]
[task 2020-09-09T01:37:34.012Z] 01:37:34     INFO - PID 14622 | 1599615454008	webdriver::server	DEBUG	<- 200 OK {"value":{"x":8.0,"y":166.6666717529297,"width":100.0,"height":50.0}}
[task 2020-09-09T01:37:34.013Z] 01:37:34     INFO - PID 14622 | 1599615454009	webdriver::server	DEBUG	-> POST /session/00d98fb5-3827-49cf-ba98-e57ef969ed76/execute/sync {"args": [], "script": "\n        return {\n          height: window.innerHeight || document.documentElement.clientHeight,\n          width: window.innerWidth || document.documentElement.clientWidth,\n        };\n    "}
[task 2020-09-09T01:37:34.014Z] 01:37:34     INFO - PID 14622 | 1599615454009	Marionette	DEBUG	0 -> [0,3932,"WebDriver:ExecuteScript",{"args":[],"script":"\n        return {\n          height: window.innerHeight || document.d ... cumentElement.clientHeight,\n          width: window.innerWidth || document.documentElement.clientWidth,\n        };\n    "}]
[task 2020-09-09T01:37:34.015Z] 01:37:34     INFO - PID 14622 | 1599615454012	Marionette	DEBUG	0 <- [1,3932,null,{"value":{"height":526,"width":800}}]
[task 2020-09-09T01:37:34.016Z] 01:37:34     INFO - PID 14622 | 1599615454012	webdriver::server	DEBUG	<- 200 OK {"value":{"height":526,"width":800}}
[task 2020-09-09T01:37:34.016Z] 01:37:34     INFO - PID 14622 | 1599615454013	webdriver::server	DEBUG	-> POST /session/00d98fb5-3827-49cf-ba98-e57ef969ed76/actions {"actions": [{"parameters": {"pointerType": "mouse"}, "type": "pointer", "id": "pointer_id", "actions": [{"y": 191, "x": 58, "type": "pointerMove"}, {"button": 0, "type": "pointerDown"}, {"button": 0, "type": "pointerUp"}, {"button": 0, "type": "pointerDown"}, {"duration": 650, "type": "pause"}, {"button": 0, "type": "pointerUp"}]}]}
[task 2020-09-09T01:37:34.018Z] 01:37:34     INFO - PID 14622 | 1599615454013	Marionette	DEBUG	0 -> [0,3933,"WebDriver:PerformActions",{"actions":[{"actions":[{"origin":"viewport","type":"pointerMove","x":58,"y":191},{"button ... ,"type":"pause"},{"button":0,"type":"pointerUp"}],"id":"pointer_id","parameters":{"pointerType":"mouse"},"type":"pointer"}]}]
[task 2020-09-09T01:37:34.033Z] 01:37:34     INFO - PID 14622 | DEBUG: Adding blocker UserInteractionTimer 148 for document 7f3359c9d000 for phase xpcom-will-shutdown
[task 2020-09-09T01:37:34.677Z] 01:37:34     INFO - PID 14622 | 1599615454672	Marionette	DEBUG	0 <- [1,3933,null,{"value":null}]
[task 2020-09-09T01:37:34.678Z] 01:37:34     INFO - PID 14622 | 1599615454672	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2020-09-09T01:37:34.678Z] 01:37:34     INFO - PID 14622 | 1599615454673	webdriver::server	DEBUG	-> POST /session/00d98fb5-3827-49cf-ba98-e57ef969ed76/frame {"id": null}
[task 2020-09-09T01:37:34.678Z] 01:37:34     INFO - PID 14622 | 1599615454674	Marionette	DEBUG	0 -> [0,3934,"WebDriver:SwitchToFrame",{"id":null}]
[task 2020-09-09T01:37:34.680Z] 01:37:34     INFO - PID 14622 | 1599615454676	Marionette	DEBUG	0 <- [1,3934,null,{"value":null}]
[task 2020-09-09T01:37:34.680Z] 01:37:34     INFO - PID 14622 | 1599615454676	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2020-09-09T01:37:34.681Z] 01:37:34     INFO - PID 14622 | 1599615454677	webdriver::server	DEBUG	-> POST /session/00d98fb5-3827-49cf-ba98-e57ef969ed76/execute/sync {"args": [], "script": "return allEvents.events;"}
[task 2020-09-09T01:37:34.682Z] 01:37:34     INFO - PID 14622 | 1599615454679	Marionette	DEBUG	0 -> [0,3935,"WebDriver:ExecuteScript",{"args":[],"script":"return allEvents.events;"}]
[task 2020-09-09T01:37:34.685Z] 01:37:34     INFO - PID 14622 | 1599615454683	Marionette	DEBUG	0 <- [1,3935,null,{"value":[{"type":"mousemove","button":0,"buttons":0,"pageX":58,"pageY":191,"ctrlKey":false,"metaKey":false,"alt ... on":0,"buttons":0,"pageX":58,"pageY":191,"ctrlKey":false,"metaKey":false,"altKey":false,"shiftKey":false,"target":"outer"}]}]
[task 2020-09-09T01:37:34.687Z] 01:37:34     INFO - STDOUT: PASSED
[task 2020-09-09T01:37:34.687Z] 01:37:34     INFO - PID 14622 | 1599615454683	webdriver::server	DEBUG	<- 200 OK {"value":[{"altKey":false,"button":0,"buttons":0,"ctrlKey":false,"metaKey":false,"pageX":58,"pageY":191,"shiftKey":false,"target":"outer","type":"mousemove"},{"altKey":false,"button":0,"buttons":1,"ctrlKey":false,"metaKey":false,"pageX":58,"pageY":191,"shiftKey":false,"target":"outer","type":"mousedown"},{"altKey":false,"button":0,"buttons":0,"ctrlKey":false,"metaKey":false,"pageX":58,"pageY":191,"shiftKey":false,"target":"outer","type":"mouseup"},{"altKey":false,"button":0,"buttons":0,"ctrlKey":false,"metaKey":false,"pageX":58,"pageY":191,"shiftKey":false,"target":"outer","type":"click"},{"altKey":false,"button":0,"buttons":1,"ctrlKey":false,"metaKey":false,"pageX":58,"pageY":191,"shiftKey":false,"target":"outer","type":"mousedown"},{"altKey":false,"button":0,"buttons":0,"ctrlKey":false,"metaKey":false,"pageX":58,"pageY":191,"shiftKey":false,"target":"outer","type":"mouseup"},{"altKey":false,"button":0,"buttons":0,"ctrlKey":false,"metaKey":false,"pageX":58,"pageY":191,"shiftKey":false,"target":"outer","type":"click"},{"altKey":false,"button":0,"buttons":0,"ctrlKey":false,"metaKey":false,"pageX":58,"pageY":191,"shiftKey":false,"target":"outer","type":"dblclick"}]}
[task 2020-09-09T01:37:34.691Z] 01:37:34     INFO - PID 14622 | 1599615454685	webdriver::server	DEBUG	-> DELETE /session/00d98fb5-3827-49cf-ba98-e57ef969ed76/actions
[task 2020-09-09T01:37:34.692Z] 01:37:34     INFO - PID 14622 | 1599615454686	Marionette	DEBUG	0 -> [0,3936,"WebDriver:ReleaseActions",{}]
[task 2020-09-09T01:37:34.692Z] 01:37:34     INFO - PID 14622 | 1599615454688	Marionette	DEBUG	0 <- [1,3936,null,{"value":null}]
[task 2020-09-09T01:37:34.692Z] 01:37:34     INFO - PID 14622 | 1599615454688	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2020-09-09T01:37:34.692Z] 01:37:34     INFO - PID 14622 | 1599615454689	webdriver::server	DEBUG	-> POST /session/00d98fb5-3827-49cf-ba98-e57ef969ed76/timeouts {"implicit": 0}
[task 2020-09-09T01:37:34.694Z] 01:37:34     INFO - PID 14622 | 1599615454690	Marionette	DEBUG	0 -> [0,3937,"WebDriver:SetTimeouts",{"implicit":0}]
[task 2020-09-09T01:37:34.697Z] 01:37:34     INFO - PID 14622 | 1599615454690	Marionette	DEBUG	0 <- [1,3937,null,{"value":null}]
[task 2020-09-09T01:37:34.697Z] 01:37:34     INFO - PID 14622 | 1599615454690	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2020-09-09T01:37:34.697Z] 01:37:34     INFO - PID 14622 | 1599615454691	webdriver::server	DEBUG	-> POST /session/00d98fb5-3827-49cf-ba98-e57ef969ed76/timeouts {"pageLoad": 300000}
[task 2020-09-09T01:37:34.698Z] 01:37:34     INFO - PID 14622 | 1599615454691	Marionette	DEBUG	0 -> [0,3938,"WebDriver:SetTimeouts",{"pageLoad":300000}]
[task 2020-09-09T01:37:34.699Z] 01:37:34     INFO - PID 14622 | 1599615454692	Marionette	DEBUG	0 <- [1,3938,null,{"value":null}]
[task 2020-09-09T01:37:34.704Z] 01:37:34     INFO - PID 14622 | 1599615454692	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2020-09-09T01:37:34.705Z] 01:37:34     INFO - PID 14622 | 1599615454694	webdriver::server	DEBUG	-> POST /session/00d98fb5-3827-49cf-ba98-e57ef969ed76/timeouts {"script": 30000}
[task 2020-09-09T01:37:34.705Z] 01:37:34     INFO - PID 14622 | 1599615454694	Marionette	DEBUG	0 -> [0,3939,"WebDriver:SetTimeouts",{"script":30000}]
[task 2020-09-09T01:37:34.705Z] 01:37:34     INFO - PID 14622 | 1599615454694	Marionette	DEBUG	0 <- [1,3939,null,{"value":null}]
[task 2020-09-09T01:37:34.706Z] 01:37:34     INFO - PID 14622 | 1599615454694	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2020-09-09T01:37:34.706Z] 01:37:34     INFO - PID 14622 | 1599615454695	webdriver::server	DEBUG	-> GET /session/00d98fb5-3827-49cf-ba98-e57ef969ed76/window
[task 2020-09-09T01:37:34.706Z] 01:37:34     INFO - PID 14622 | 1599615454696	Marionette	DEBUG	0 -> [0,3940,"WebDriver:GetWindowHandle",{}]
[task 2020-09-09T01:37:34.706Z] 01:37:34     INFO - PID 14622 | 1599615454696	Marionette	DEBUG	0 <- [1,3940,null,{"value":"17"}]
[task 2020-09-09T01:37:34.706Z] 01:37:34     INFO - PID 14622 | 1599615454696	webdriver::server	DEBUG	<- 200 OK {"value":"17"}
[task 2020-09-09T01:37:34.706Z] 01:37:34     INFO - PID 14622 | 1599615454697	webdriver::server	DEBUG	-> GET /session/00d98fb5-3827-49cf-ba98-e57ef969ed76/window
[task 2020-09-09T01:37:34.707Z] 01:37:34     INFO - PID 14622 | 1599615454697	Marionette	DEBUG	0 -> [0,3941,"WebDriver:GetWindowHandle",{}]
[task 2020-09-09T01:37:34.707Z] 01:37:34     INFO - PID 14622 | 1599615454698	Marionette	DEBUG	0 <- [1,3941,null,{"value":"17"}]
[task 2020-09-09T01:37:34.707Z] 01:37:34     INFO - PID 14622 | 1599615454698	webdriver::server	DEBUG	<- 200 OK {"value":"17"}
[task 2020-09-09T01:37:34.707Z] 01:37:34     INFO - PID 14622 | 1599615454699	webdriver::server	DEBUG	-> GET /session/00d98fb5-3827-49cf-ba98-e57ef969ed76/window/handles
[task 2020-09-09T01:37:34.707Z] 01:37:34     INFO - PID 14622 | 1599615454700	Marionette	DEBUG	0 -> [0,3942,"WebDriver:GetWindowHandles",{}]
[task 2020-09-09T01:37:34.707Z] 01:37:34     INFO - PID 14622 | 1599615454700	Marionette	DEBUG	0 <- [1,3942,null,["17"]]
[task 2020-09-09T01:37:34.707Z] 01:37:34     INFO - PID 14622 | 1599615454700	webdriver::server	DEBUG	<- 200 OK {"value":["17"]}
[task 2020-09-09T01:37:34.708Z] 01:37:34     INFO - PID 14622 | 1599615454701	webdriver::server	DEBUG	-> POST /session/00d98fb5-3827-49cf-ba98-e57ef969ed76/window {"handle": "17"}
[task 2020-09-09T01:37:34.708Z] 01:37:34     INFO - PID 14622 | 1599615454701	Marionette	DEBUG	0 -> [0,3943,"WebDriver:SwitchToWindow",{"handle":"17","name":"17"}]
[task 2020-09-09T01:37:34.714Z] 01:37:34     INFO - PID 14622 | 1599615454701	Marionette	DEBUG	0 <- [1,3943,null,{"value":null}]
[task 2020-09-09T01:37:34.714Z] 01:37:34     INFO - PID 14622 | 1599615454702	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2020-09-09T01:37:34.715Z] 01:37:34     INFO - PID 14622 | 1599615454703	webdriver::server	DEBUG	-> POST /session/00d98fb5-3827-49cf-ba98-e57ef969ed76/alert/dismiss {}
[task 2020-09-09T01:37:34.715Z] 01:37:34     INFO - PID 14622 | 1599615454703	Marionette	DEBUG	0 -> [0,3944,"WebDriver:DismissAlert",{}]
[task 2020-09-09T01:37:34.716Z] 01:37:34     INFO - PID 14622 | 1599615454704	Marionette	DEBUG	0 <- [1,3944,{"error":"no such alert","message":"","stacktrace":"WebDriverError@chrome://marionette/content/error.js:175:5\nNoSuch ... t@chrome://marionette/content/server.js:247:9\n_onJSONObjectReady/<@chrome://marionette/content/transport.js:501:20\n"},null]
[task 2020-09-09T01:37:34.716Z] 01:37:34     INFO - PID 14622 | 1599615454704	webdriver::server	DEBUG	<- 404 Not Found {"value":{"error":"no such alert","message":"","stacktrace":"WebDriverError@chrome://marionette/content/error.js:175:5\nNoSuchAlertError@chrome://marionette/content/error.js:376:5\nGeckoDriver.prototype._checkIfAlertIsPresent@chrome://marionette/content/driver.js:3381:11\nGeckoDriver.prototype.dismissDialog@chrome://marionette/content/driver.js:3294:8\ndespatch@chrome://marionette/content/server.js:303:40\nexecute@chrome://marionette/content/server.js:273:16\nonPacket/<@chrome://marionette/content/server.js:246:20\nonPacket@chrome://marionette/content/server.js:247:9\n_onJSONObjectReady/<@chrome://marionette/content/transport.js:501:20\n"}}
[task 2020-09-09T01:37:34.716Z] 01:37:34     INFO - PID 14622 | 1599615454706	webdriver::server	DEBUG	-> POST /session/00d98fb5-3827-49cf-ba98-e57ef969ed76/window {"handle": "17"}
[task 2020-09-09T01:37:34.717Z] 01:37:34     INFO - PID 14622 | 1599615454707	Marionette	DEBUG	0 -> [0,3945,"WebDriver:SwitchToWindow",{"handle":"17","name":"17"}]
[task 2020-09-09T01:37:34.717Z] 01:37:34     INFO - PID 14622 | 1599615454707	Marionette	DEBUG	0 <- [1,3945,null,{"value":null}]
[task 2020-09-09T01:37:34.717Z] 01:37:34     INFO - PID 14622 | 1599615454708	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2020-09-09T01:37:34.717Z] 01:37:34     INFO - PID 14622 | 1599615454709	webdriver::server	DEBUG	-> GET /session/00d98fb5-3827-49cf-ba98-e57ef969ed76/window
[task 2020-09-09T01:37:34.717Z] 01:37:34     INFO - PID 14622 | 1599615454709	Marionette	DEBUG	0 -> [0,3946,"WebDriver:GetWindowHandle",{}]
[task 2020-09-09T01:37:34.718Z] 01:37:34     INFO - PID 14622 | 1599615454710	Marionette	DEBUG	0 <- [1,3946,null,{"value":"17"}]
[task 2020-09-09T01:37:34.718Z] 01:37:34     INFO - PID 14622 | 1599615454710	webdriver::server	DEBUG	<- 200 OK {"value":"17"}
[task 2020-09-09T01:37:34.718Z] 01:37:34     INFO - PID 14622 | 1599615454711	webdriver::server	DEBUG	-> GET /session/00d98fb5-3827-49cf-ba98-e57ef969ed76/window/handles
[task 2020-09-09T01:37:34.718Z] 01:37:34     INFO - PID 14622 | 1599615454711	Marionette	DEBUG	0 -> [0,3947,"WebDriver:GetWindowHandles",{}]
[task 2020-09-09T01:37:34.719Z] 01:37:34     INFO - PID 14622 | 1599615454711	Marionette	DEBUG	0 <- [1,3947,null,["17"]]
[task 2020-09-09T01:37:34.719Z] 01:37:34     INFO - PID 14622 | 1599615454711	webdriver::server	DEBUG	<- 200 OK {"value":["17"]}
[task 2020-09-09T01:37:34.719Z] 01:37:34     INFO - PID 14622 | 1599615454713	webdriver::server	DEBUG	-> POST /session/00d98fb5-3827-49cf-ba98-e57ef969ed76/window {"handle": "17"}
[task 2020-09-09T01:37:34.720Z] 01:37:34     INFO - PID 14622 | 1599615454713	Marionette	DEBUG	0 -> [0,3948,"WebDriver:SwitchToWindow",{"handle":"17","name":"17"}]
[task 2020-09-09T01:37:34.720Z] 01:37:34     INFO - PID 14622 | 1599615454713	Marionette	DEBUG	0 <- [1,3948,null,{"value":null}]
[task 2020-09-09T01:37:34.721Z] 01:37:34     INFO - PID 14622 | 1599615454713	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2020-09-09T01:37:34.722Z] 01:37:34     INFO - PID 14622 | 1599615454714	webdriver::server	DEBUG	-> POST /session/00d98fb5-3827-49cf-ba98-e57ef969ed76/window/rect {"width": 800, "height": 600}
[task 2020-09-09T01:37:34.722Z] 01:37:34     INFO - PID 14622 | 1599615454715	Marionette	DEBUG	0 -> [0,3949,"WebDriver:SetWindowRect",{"height":600,"width":800}]
[task 2020-09-09T01:37:34.726Z] 01:37:34     INFO - PID 14622 | 1599615454719	Marionette	DEBUG	0 <- [1,3949,null,{"x":100,"y":100,"width":800,"height":600}]
[task 2020-09-09T01:37:34.726Z] 01:37:34     INFO - STDOUT: tests/web-platform/tests/webdriver/tests/perform_actions/pointer_pause_dblclick.py::test_no_dblclick 
[task 2020-09-09T01:37:34.726Z] 01:37:34     INFO - PID 14622 | 1599615454719	webdriver::server	DEBUG	<- 200 OK {"value":{"x":100,"y":100,"width":800,"height":600}}
[task 2020-09-09T01:37:34.728Z] 01:37:34     INFO - PID 14622 | 1599615454720	webdriver::server	DEBUG	-> POST /session/00d98fb5-3827-49cf-ba98-e57ef969ed76/frame {"id": null}
[task 2020-09-09T01:37:34.728Z] 01:37:34     INFO - PID 14622 | 1599615454721	Marionette	DEBUG	0 -> [0,3950,"WebDriver:SwitchToFrame",{"id":null}]
[task 2020-09-09T01:37:34.728Z] 01:37:34     INFO - PID 14622 | 1599615454722	Marionette	DEBUG	0 <- [1,3950,null,{"value":null}]
[task 2020-09-09T01:37:34.729Z] 01:37:34     INFO - PID 14622 | 1599615454722	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2020-09-09T01:37:34.730Z] 01:37:34     INFO - PID 14622 | 1599615454724	webdriver::server	DEBUG	-> POST /session/00d98fb5-3827-49cf-ba98-e57ef969ed76/window/rect {"width": 800, "height": 600}
[task 2020-09-09T01:37:34.731Z] 01:37:34     INFO - PID 14622 | 1599615454725	Marionette	DEBUG	0 -> [0,3951,"WebDriver:SetWindowRect",{"height":600,"width":800}]
[task 2020-09-09T01:37:34.731Z] 01:37:34     INFO - PID 14622 | 1599615454725	Marionette	DEBUG	0 <- [1,3951,null,{"x":100,"y":100,"width":800,"height":600}]
[task 2020-09-09T01:37:34.731Z] 01:37:34     INFO - PID 14622 | 1599615454726	webdriver::server	DEBUG	<- 200 OK {"value":{"x":100,"y":100,"width":800,"height":600}}
[task 2020-09-09T01:37:34.733Z] 01:37:34     INFO - PID 14622 | 1599615454727	webdriver::server	DEBUG	-> POST /session/00d98fb5-3827-49cf-ba98-e57ef969ed76/window/rect {"y": 100, "x": 100}
[task 2020-09-09T01:37:34.733Z] 01:37:34     INFO - PID 14622 | 1599615454727	Marionette	DEBUG	0 -> [0,3952,"WebDriver:SetWindowRect",{"x":100,"y":100}]
[task 2020-09-09T01:37:34.733Z] 01:37:34     INFO - PID 14622 | 1599615454728	Marionette	DEBUG	0 <- [1,3952,null,{"x":100,"y":100,"width":800,"height":600}]
[task 2020-09-09T01:37:34.733Z] 01:37:34     INFO - PID 14622 | 1599615454728	webdriver::server	DEBUG	<- 200 OK {"value":{"x":100,"y":100,"width":800,"height":600}}
[task 2020-09-09T01:37:34.735Z] 01:37:34     INFO - PID 14622 | 1599615454730	webdriver::server	DEBUG	-> POST /session/00d98fb5-3827-49cf-ba98-e57ef969ed76/url {"url": "http://web-platform.test:8000/webdriver/tests/perform_actions/support/test_actions_wdspec.html"}
[task 2020-09-09T01:37:34.735Z] 01:37:34     INFO - PID 14622 | 1599615454731	Marionette	DEBUG	0 -> [0,3953,"WebDriver:Navigate",{"url":"http://web-platform.test:8000/webdriver/tests/perform_actions/support/test_actions_wdspec.html"}]
[task 2020-09-09T01:37:34.736Z] 01:37:34     INFO - PID 14622 | 1599615454732	Marionette	TRACE	Using browsing context 17
[task 2020-09-09T01:37:34.737Z] 01:37:34     INFO - PID 14622 | 1599615454734	Marionette	TRACE	[17] Received DOM event beforeunload for http://web-platform.test:8000/webdriver/tests/perform_actions/support/test_actions_wdspec.html
[task 2020-09-09T01:37:34.752Z] 01:37:34     INFO - PID 14622 | 1599615454744	Marionette	TRACE	[17] Received DOM event pagehide for http://web-platform.test:8000/webdriver/tests/perform_actions/support/test_actions_wdspec.html
[task 2020-09-09T01:37:34.754Z] 01:37:34     INFO - PID 14622 | 1599615454751	Marionette	TRACE	[17] Received DOM event DOMContentLoaded for http://web-platform.test:8000/webdriver/tests/perform_actions/support/test_actions_wdspec.html
[task 2020-09-09T01:37:34.761Z] 01:37:34     INFO - PID 14622 | 1599615454755	Marionette	TRACE	[17] Received DOM event pageshow for http://web-platform.test:8000/webdriver/tests/perform_actions/support/test_actions_wdspec.html
[task 2020-09-09T01:37:34.761Z] 01:37:34     INFO - PID 14622 | 1599615454756	Marionette	DEBUG	0 <- [1,3953,null,{"value":null}]
[task 2020-09-09T01:37:34.762Z] 01:37:34     INFO - PID 14622 | 1599615454758	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2020-09-09T01:37:34.763Z] 01:37:34     INFO - PID 14622 | 1599615454759	webdriver::server	DEBUG	-> POST /session/00d98fb5-3827-49cf-ba98-e57ef969ed76/element {"using": "css selector", "value": "#outer"}
[task 2020-09-09T01:37:34.763Z] 01:37:34     INFO - PID 14622 | 1599615454760	Marionette	DEBUG	0 -> [0,3954,"WebDriver:FindElement",{"using":"css selector","value":"#outer"}]
[task 2020-09-09T01:37:34.771Z] 01:37:34     INFO - PID 14622 | 1599615454764	Marionette	DEBUG	0 <- [1,3954,null,{"value":{"element-6066-11e4-a52e-4f735466cecf":"c2a7b5fc-3df0-4f24-8795-94745f327485"}}]
[task 2020-09-09T01:37:34.772Z] 01:37:34     INFO - PID 14622 | 1599615454765	webdriver::server	DEBUG	<- 200 OK {"value":{"element-6066-11e4-a52e-4f735466cecf":"c2a7b5fc-3df0-4f24-8795-94745f327485"}}
[task 2020-09-09T01:37:34.773Z] 01:37:34     INFO - PID 14622 | 1599615454766	webdriver::server	DEBUG	-> GET /session/00d98fb5-3827-49cf-ba98-e57ef969ed76/element/c2a7b5fc-3df0-4f24-8795-94745f327485/rect
[task 2020-09-09T01:37:34.773Z] 01:37:34     INFO - PID 14622 | 1599615454766	Marionette	DEBUG	0 -> [0,3955,"WebDriver:GetElementRect",{"id":"c2a7b5fc-3df0-4f24-8795-94745f327485"}]
[task 2020-09-09T01:37:34.773Z] 01:37:34     INFO - PID 14622 | 1599615454767	Marionette	DEBUG	0 <- [1,3955,null,{"x":8,"y":166.6666717529297,"width":100,"height":50}]
[task 2020-09-09T01:37:34.774Z] 01:37:34     INFO - PID 14622 | 1599615454767	webdriver::server	DEBUG	<- 200 OK {"value":{"x":8.0,"y":166.6666717529297,"width":100.0,"height":50.0}}
[task 2020-09-09T01:37:34.775Z] 01:37:34     INFO - PID 14622 | 1599615454768	webdriver::server	DEBUG	-> POST /session/00d98fb5-3827-49cf-ba98-e57ef969ed76/execute/sync {"args": [], "script": "\n        return {\n          height: window.innerHeight || document.documentElement.clientHeight,\n          width: window.innerWidth || document.documentElement.clientWidth,\n        };\n    "}
[task 2020-09-09T01:37:34.776Z] 01:37:34     INFO - PID 14622 | 1599615454768	Marionette	DEBUG	0 -> [0,3956,"WebDriver:ExecuteScript",{"args":[],"script":"\n        return {\n          height: window.innerHeight || document.d ... cumentElement.clientHeight,\n          width: window.innerWidth || document.documentElement.clientWidth,\n        };\n    "}]
[task 2020-09-09T01:37:34.776Z] 01:37:34     INFO - PID 14622 | 1599615454770	Marionette	DEBUG	0 <- [1,3956,null,{"value":{"height":526,"width":800}}]
[task 2020-09-09T01:37:34.781Z] 01:37:34     INFO - PID 14622 | 1599615454775	webdriver::server	DEBUG	<- 200 OK {"value":{"height":526,"width":800}}
[task 2020-09-09T01:37:34.781Z] 01:37:34     INFO - PID 14622 | 1599615454776	webdriver::server	DEBUG	-> POST /session/00d98fb5-3827-49cf-ba98-e57ef969ed76/actions {"actions": [{"parameters": {"pointerType": "mouse"}, "type": "pointer", "id": "pointer_id", "actions": [{"y": 191, "x": 58, "type": "pointerMove"}, {"button": 0, "type": "pointerDown"}, {"button": 0, "type": "pointerUp"}, {"duration": 650, "type": "pause"}, {"button": 0, "type": "pointerDown"}, {"button": 0, "type": "pointerUp"}]}]}
[task 2020-09-09T01:37:34.782Z] 01:37:34     INFO - PID 14622 | 1599615454777	Marionette	DEBUG	0 -> [0,3957,"WebDriver:PerformActions",{"actions":[{"actions":[{"origin":"viewport","type":"pointerMove","x":58,"y":191},{"button ... ":"pointerDown"},{"button":0,"type":"pointerUp"}],"id":"pointer_id","parameters":{"pointerType":"mouse"},"type":"pointer"}]}]
[task 2020-09-09T01:37:34.797Z] 01:37:34     INFO - PID 14622 | DEBUG: Adding blocker UserInteractionTimer 149 for document 7f335d9e5000 for phase xpcom-will-shutdown
[task 2020-09-09T01:37:38.051Z] 01:37:38     INFO - PID 14622 | DEBUG: Adding blocker SessionFile: Finish writing Session Restore data for phase profile-before-change
[task 2020-09-09T01:37:38.051Z] 01:37:38     INFO - PID 14622 | DEBUG: Completed blocker SessionFile: Finish writing Session Restore data for phase profile-before-change
[task 2020-09-09T01:38:03.942Z] 01:38:03     INFO - TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/perform_actions/pointer_pause_dblclick.py | expected OK
[task 2020-09-09T01:38:03.942Z] 01:38:03     INFO - TEST-INFO took 30002ms
...

Flags: needinfo?(hskupin)

Henrik Skupin [:whimboo][⌚️UTC+1]

Assignee

Comment 9

•

4 years ago

The code in question here is:

+  return new Promise(resolve => {
+    const timer = Cc["@mozilla.org/timer;1"].createInstance(Ci.nsITimer);
+    timer.init(resolve, timeout, TYPE_ONE_SHOT);
+  });

When I add dump statements before calling init() and inside a callback wrapping resolve I can see that the timer never fires! It does't matter which value as timeout is passed in here. It's just randomly hanging. I also tried with initWithCallback but the same problem exists there.

I can reproduce easily when running the wdspec tests with the patch applied on MacOS too:

cd testing/geckodriver
cargo build
cd ../../
mach wpt --webdriver-binary=target/debug/geckodriver --webdriver-arg=-vv testing/web-platform/tests/webdriver/tests/perform_actions/pointer*

Olli, are you aware of any timer issue, which could lead in not firing the callback? What's strange here is that the TimedPromise uses the same technique but never has this problem.

Flags: needinfo?(hskupin) → needinfo?(bugs)

Henrik Skupin [:whimboo][⌚️UTC+1]

Assignee

Updated

•

4 years ago

Blocks: 1663810

Henrik Skupin [:whimboo][⌚️UTC+1]

Assignee

Comment 10

•

4 years ago

So what's interesting here is that if I add an explicit timer.cancel() even for this one time shot timer, the problem goes away:

  return new Promise(resolve => {
    const timer = Cc["@mozilla.org/timer;1"].createInstance(Ci.nsITimer);
    timer.init(() => {
      timer.cancel();
      resolve();
    }, timeout, TYPE_ONE_SHOT);
  });

I assume there is a bad interaction when a couple of timers are getting created this way.

Henrik Skupin [:whimboo][⌚️UTC+1]

Assignee

Comment 11

•

4 years ago

Attached file marionette testcase (obsolete) — Details

It's actually easily reproducible with this Marionette test case. So I'm fairly sure this is a bug in the timer code. As such I will workaround the issue for now, and file a new bug with hopefully a plain JS testcase for reproduction.

Henrik Skupin [:whimboo][⌚️UTC+1]

Assignee

Updated

•

4 years ago

Depends on: 1663880

Henrik Skupin [:whimboo][⌚️UTC+1]

Assignee

Comment 12

•

4 years ago

I filed bug 1663880 for it, and will workaround the issue for now by explicitly calling cancel().

Flags: needinfo?(bugs)

Henrik Skupin [:whimboo][⌚️UTC+1]

Assignee

Updated

•

4 years ago

Attachment #9174608 - Attachment is obsolete: true

Henrik Skupin [:whimboo][⌚️UTC+1]

Assignee

Comment 13

•

4 years ago

What's also interesting the failure doesn't appear on try:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=2bab920c0453eb555d21e77d7f3469a381db08ba

As such I will have to just re-push the updated patch, given that it is working fine locally for me now.

Pulsebot

Comment 14

•

4 years ago

Pushed by hskupin@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/754d1143eedc
[marionette] Use plain Promise instead of TimedPromise for Sleep. r=marionette-reviewers,maja_zf

Dorel Luca [:dluca]

Comment 15

•

4 years ago

bugherder

https://hg.mozilla.org/mozilla-central/rev/754d1143eedc

Status: ASSIGNED → RESOLVED

Closed: 4 years ago

status-firefox82: affected → fixed

Resolution: --- → FIXED

Target Milestone: --- → 82 Branch

Henrik Skupin [:whimboo][⌚️UTC+1]

Assignee

Comment 16

•

4 years ago

Comment on attachment 9174182 [details]
Bug 1606637 - [marionette] Use plain Promise instead of TimedPromise for Sleep.

Beta/Release Uplift Approval Request

User impact if declined: Misleading error log entries in geckodriver logs, which lots of people complain about and unnecessarily fill up the disk.
Is this code covered by automated tests?: Yes
Has the fix been verified in Nightly?: Yes
Needs manual test from QE?: No
If yes, steps to reproduce:
List of other uplifts needed: None
Risk to taking this patch: Low
Why is the change risky/not risky? (and alternatives if risky): Simple code change by using a timer wrapped inside a plain Promise now.
String changes made/needed: no

Attachment #9174182 - Flags: approval-mozilla-beta?

Ryan VanderMeulen [:RyanVM]

Comment 17

•

4 years ago

Comment on attachment 9174182 [details]
Bug 1606637 - [marionette] Use plain Promise instead of TimedPromise for Sleep.

Approved for 81.0b9.

Attachment #9174182 - Flags: approval-mozilla-beta? → approval-mozilla-beta+

Ryan VanderMeulen [:RyanVM]

Comment 18

•

4 years ago

bugherder uplift

https://hg.mozilla.org/releases/mozilla-beta/rev/12845431dd09

status-firefox81: affected → fixed

BMO Automation

Updated

•

1 year ago

Product: Testing → Remote Protocol

Bug 1606637 - [marionette] Use plain Promise instead of TimedPromise for Sleep. 4 years ago Henrik Skupin [:whimboo][⌚️UTC+1] 47 bytes, text/x-phabricator-request	RyanVM : approval-mozilla-beta+	Details \| Review
marionette testcase 4 years ago Henrik Skupin [:whimboo][⌚️UTC+1] 979 bytes, text/plain		Details