Filed by: philringnalda [at] gmail.com https://treeherder.mozilla.org/logviewer.html#?job_id=148576125&repo=autoland https://queue.taskcluster.net/v1/task/EioinA2AQfeprQE1ymCkVQ/runs/0/artifacts/public/logs/live_backing.log

[task 2017-11-29T21:07:18.140Z] 21:07:18 INFO - TEST-UNEXPECTED-FAIL | /webdriver/tests/actions/mouse.py | mouse.py::test_click_element_center [task 2017-11-29T21:07:18.140Z] 21:07:18 INFO - session = <webdriver.client.Session object at 0x7f7e4bd73550> [task 2017-11-29T21:07:18.141Z] 21:07:18 INFO - test_actions_page = None [task 2017-11-29T21:07:18.141Z] 21:07:18 INFO - mouse_chain = <webdriver.client.ActionSequence object at 0x7f7e4bd73a50> [task 2017-11-29T21:07:18.141Z] 21:07:18 INFO - [task 2017-11-29T21:07:18.141Z] 21:07:18 INFO - def test_click_element_center(session, test_actions_page, mouse_chain): [task 2017-11-29T21:07:18.142Z] 21:07:18 INFO - outer = session.find.css("#outer", all=False) [task 2017-11-29T21:07:18.142Z] 21:07:18 INFO - center = get_center(outer.rect) [task 2017-11-29T21:07:18.142Z] 21:07:18 INFO - mouse_chain.click(element=outer).perform() [task 2017-11-29T21:07:18.142Z] 21:07:18 INFO - events = get_events(session) [task 2017-11-29T21:07:18.142Z] 21:07:18 INFO - > assert len(events) == 4 [task 2017-11-29T21:07:18.143Z] 21:07:18 INFO - E assert 5 == 4 [task 2017-11-29T21:07:18.143Z] 21:07:18 INFO - E + where 5 = len([{'altKey': False, 'button': 0, 'buttons': 0, 'ctrlKey': False, ...}, {'altKey': False, 'button': 0, 'buttons': 1, 'ct...'button': 0, 'buttons': 0, 'ctrlKey': False, ...}, {'altKey': False, 'button': 0, 'buttons': 0, 'ctrlKey': False, ...}]) [task 2017-11-29T21:07:18.143Z] 21:07:18 INFO - [task 2017-11-29T21:07:18.143Z] 21:07:18 INFO - center = {'x': 58.0, 'y': 190.6666717529297} [task 2017-11-29T21:07:18.144Z] 21:07:18 INFO - events = [{'altKey': False, 'button': 0, 'buttons': 0, 'ctrlKey': False, ...}, {'altKey': False, 'button': 0, 'buttons': 1, 'ct...'button': 0, 'buttons': 0, 'ctrlKey': False, ...}, {'altKey': False, 'button': 0, 'buttons': 0, 'ctrlKey': False, ...}] [task 2017-11-29T21:07:18.144Z] 21:07:18 INFO - mouse_chain = <webdriver.client.ActionSequence object at 0x7f7e4bd73a50> [task 2017-11-29T21:07:18.144Z] 21:07:18 INFO - outer = <webdriver.client.Element object at 0x7f7e4bd73590> [task 2017-11-29T21:07:18.144Z] 21:07:18 INFO - session = <webdriver.client.Session object at 0x7f7e4bd73550> [task 2017-11-29T21:07:18.144Z] 21:07:18 INFO - test_actions_page = None Maja, is that related to any of the latest mouse changes to actions?

I suspect that the extra event is a dblclick, which can happen if two consecutive tests click in quick succession -- as a result of Bug 1385476 just landing. The solution is to start a new session for each test, but that can also introduce intermittents (since the session sometimes doesn't start). Let's see how often this click failure happens.

There have been 34 failures in the last 7 days. The most failures are occurring on the Linux platform, but there also some occurring on Linux x64 and linux64-ccov. The most affected build type is debug with 28 failures. There are also 6 failure occurring on opt. Here is a recent log: https://treeherder.mozilla.org/logviewer.html#?repo=autoland&job_id=150898573&lineNumber=2239 And a relevant snippet from it: [task 2017-12-08T21:39:08.984Z] 21:39:08 INFO - TEST-PASS | /webdriver/tests/actions/mouse.py | mouse.py::test_click_at_coordinates 2238 [task 2017-12-08T21:39:08.984Z] 21:39:08 INFO - TEST-PASS | /webdriver/tests/actions/mouse.py | mouse.py::test_context_menu_at_coordinates 2239 [task 2017-12-08T21:39:08.985Z] 21:39:08 INFO - TEST-UNEXPECTED-FAIL | /webdriver/tests/actions/mouse.py | mouse.py::test_click_element_center 2240 [task 2017-12-08T21:39:08.985Z] 21:39:08 INFO - session = <webdriver.client.Session object at 0x7fbe14cf49d0> 2241 [task 2017-12-08T21:39:08.986Z] 21:39:08 INFO - test_actions_page = None 2242 [task 2017-12-08T21:39:08.986Z] 21:39:08 INFO - mouse_chain = <webdriver.client.ActionSequence object at 0x7fbe14cf4c90> 2243 [task 2017-12-08T21:39:08.987Z] 21:39:08 INFO - 2244 [task 2017-12-08T21:39:08.987Z] 21:39:08 INFO - def test_click_element_center(session, test_actions_page, mouse_chain): 2245 [task 2017-12-08T21:39:08.988Z] 21:39:08 INFO - outer = session.find.css("#outer", all=False) 2246 [task 2017-12-08T21:39:08.988Z] 21:39:08 INFO - center = get_center(outer.rect) 2247 [task 2017-12-08T21:39:08.989Z] 21:39:08 INFO - mouse_chain.click(element=outer).perform() 2248 [task 2017-12-08T21:39:08.989Z] 21:39:08 INFO - events = get_events(session) 2249 [task 2017-12-08T21:39:08.989Z] 21:39:08 INFO - > assert len(events) == 4 2250 [task 2017-12-08T21:39:08.989Z] 21:39:08 INFO - E assert 5 == 4 2251 [task 2017-12-08T21:39:08.990Z] 21:39:08 INFO - E + where 5 = len([{'altKey': False, 'button': 0, 'buttons': 0, 'ctrlKey': False, ...}, {'altKey': False, 'button': 0, 'buttons': 1, 'ct...'button': 0, 'buttons': 0, 'ctrlKey': False, ...}, {'altKey': False, 'button': 0, 'buttons': 0, 'ctrlKey': False, ...}]) 2252 [task 2017-12-08T21:39:08.990Z] 21:39:08 INFO - 2253 [task 2017-12-08T21:39:08.990Z] 21:39:08 INFO - center = {'x': 58.0, 'y': 190.6666717529297} 2254 [task 2017-12-08T21:39:08.991Z] 21:39:08 INFO - events = [{'altKey': False, 'button': 0, 'buttons': 0, 'ctrlKey': False, ...}, {'altKey': False, 'button': 0, 'buttons': 1, 'ct...'button': 0, 'buttons': 0, 'ctrlKey': False, ...}, {'altKey': False, 'button': 0, 'buttons': 0, 'ctrlKey': False, ...}] 2255 [task 2017-12-08T21:39:08.991Z] 21:39:08 INFO - mouse_chain = <webdriver.client.ActionSequence object at 0x7fbe14cf4c90> 2256 [task 2017-12-08T21:39:08.991Z] 21:39:08 INFO - outer = <webdriver.client.Element object at 0x7fbe14cf4990> 2257 [task 2017-12-08T21:39:08.992Z] 21:39:08 INFO - session = <webdriver.client.Session object at 0x7fbe14cf49d0> 2258 [task 2017-12-08T21:39:08.992Z] 21:39:08 INFO - test_actions_page = None 2259 [task 2017-12-08T21:39:08.992Z] 21:39:08 INFO - 2260 [task 2017-12-08T21:39:08.993Z] 21:39:08 INFO - tests/web-platform/tests/webdriver/tests/actions/mouse.py:73: AssertionError

There have been 33 failures in the last 7 days. For failure pattern, please see Comment 4 A recent log: https://treeherder.mozilla.org/logviewer.html#?repo=mozilla-central&job_id=152611829&lineNumber=2503

Maja this test fails a lot. Would you have the time to check what we can do here?

I'll take a look this week. Leaving the n-i on so I don't forget.

Comment on attachment 8942387 [details] Bug 1421878 - Reset Marionette's click state on document unload; https://reviewboard.mozilla.org/r/212672/#review218532 This patch mixes up two different issues. Lets really only focus on the extra pause on this bug. ::: commit-message-ac93f:15 (Diff revision 1) > +independent, let's add a pause after tests that involve a click. > + > +If this works well for fixing the intermittent we're seeing, I > +could also use this pause for dblclick and modifier-click tests > +as an alternative to starting a new session between each test. > + Great. But also lets make sure we continue on what we discussed last week. Finishing an action chain it might make sense to reset this flag - which would most likely need a discussion in a WebDriver spec issue.

Comment on attachment 8942387 [details] Bug 1421878 - Reset Marionette's click state on document unload; https://reviewboard.mozilla.org/r/212672/#review218532 Sorry, Henrik, I don't understand. What else is this patch doing, besides adding a pause, in your view? What is being mixed up? > Great. But also lets make sure we continue on what we discussed last week. Finishing an action chain it might make sense to reset this flag - which would most likely need a discussion in a WebDriver spec issue. I filed https://github.com/w3c/webdriver/issues/1197 but I don't think that should delay us from landing this tentative fix.

Comment on attachment 8942387 [details] Bug 1421878 - Reset Marionette's click state on document unload; https://reviewboard.mozilla.org/r/212672/#review218532 I was referring to the changes for the approx helper, and the move of the drag and drop test, which doesn't seem to belong here. > I filed https://github.com/w3c/webdriver/issues/1197 but I don't think that should delay us from landing this tentative fix. No it doesnt. I just don't want that we forget about it.

Comment on attachment 8942387 [details] Bug 1421878 - Reset Marionette's click state on document unload; https://reviewboard.mozilla.org/r/212672/#review218532 I need to move the drag and drop because it will hit a timeout with the new pauses otherwise. I need to move the approx helper so that I can be shared across both test files.

I see. So I talked with Andreas in our chit chat today about this issue, and he mentioned to me that this might not happen if a different input device would be used by each test. In such a case we should not retain the state from a former click. Also we won't need a sleep at all. Would you mind to check that?

(In reply to Henrik Skupin (:whimboo) from comment #23) > I see. So I talked with Andreas in our chit chat today about this issue, and > he mentioned to me that this might not happen if a different input device > would be used by each test. In such a case we should not retain the state > from a former click. Also we won't need a sleep at all. > > Would you mind to check that? I got a better idea from https://bugzilla.mozilla.org/show_bug.cgi?id=1430851#c2 -- reset the click timer on document unload. Regarding using different input devices, I don't think it would be correct to use that to avoid "extra dblclicks". For example, I looked at the events emitted by Firefox (outside of automation, i.e. real life) by clicking with my track pad and my mouse in quick succession: Firefox still sees that as a dblclick even though the individual clicks were triggered by different devices.

Comment on attachment 8942387 [details] Bug 1421878 - Reset Marionette's click state on document unload; https://reviewboard.mozilla.org/r/212672/#review219854 Removing review request to wait for the new idea. :) It sounds better, yes.

Comment on attachment 8942387 [details] Bug 1421878 - Reset Marionette's click state on document unload; https://reviewboard.mozilla.org/r/212672/#review220160 Yes, that looks way better! If that works we can even remove the restarts, without having to add sleeps or whatever else.

Pushed by hskupin@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/87986a428a98 Reset Marionette's click state on document unload; r=whimboo

Moving bug to Remote Protocol::Marionette component per bug 1815831.