1580401 - Debian 10 - testing/marionette/harness/marionette_harness/tests/unit/test_mouse_action.py TestPointerActions.test_context_click_action | TimeoutException: Timed out after 5.0 seconds with message: Context menu did not open

Status: RESOLVED INACTIVE

(Remote Protocol :: Marionette, defect, P5)

Description

[Treeherder Bug Filer]

Filed by: egao [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=265784041&repo=try
Full log: https://queue.taskcluster.net/v1/task/cyml0iAsR4yxKwbPYK0IYQ/runs/0/artifacts/public/logs/live_backing.log

---

Platform: debian 10
Suite: marionette

Context:
[task 2019-09-09T20:51:34.409Z] 20:51:34 INFO - TEST-START | testing/marionette/harness/marionette_harness/tests/unit/test_mouse_action.py TestNonSpecCompliantPointerOrigin.test_click_element_larger_than_viewport_with_center_point_inside
[task 2019-09-09T20:51:34.409Z] 20:51:34 INFO - 1568062294408 Marionette DEBUG Closed connection 72
[task 2019-09-09T20:51:34.412Z] 20:51:34 INFO - 1568062294408 Marionette DEBUG Accepted connection 73 from 127.0.0.1:59490
[task 2019-09-09T20:51:34.420Z] 20:51:34 INFO - 1568062294418 Marionette DEBUG 73 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
[task 2019-09-09T20:51:34.421Z] 20:51:34 INFO - 1568062294419 Marionette TRACE [5] Frame script loaded
[task 2019-09-09T20:51:34.425Z] 20:51:34 INFO - 1568062294422 Marionette TRACE [5] Frame script registered
[task 2019-09-09T20:51:34.425Z] 20:51:34 INFO - 1568062294423 Marionette DEBUG 73 <- [1,1,null,{"sessionId":"a49feacc-dd4f-4088-868a-e21e33f7ca7a","capabilities":{"browserName":"firefox","browserVersion":"71.0a ... mp/tmpYxRbR0.mozrunner","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true}}]
[task 2019-09-09T20:51:34.425Z] 20:51:34 INFO - 1568062294424 Marionette DEBUG 73 -> [0,2,"WebDriver:SetTimeouts",{"script":30000}]
[task 2019-09-09T20:51:34.425Z] 20:51:34 INFO - 1568062294424 Marionette DEBUG 73 <- [1,2,null,{"value":null}]
[task 2019-09-09T20:51:34.426Z] 20:51:34 INFO - 1568062294424 Marionette DEBUG 73 -> [0,3,"WebDriver:SetTimeouts",{"pageLoad":300000}]
[task 2019-09-09T20:51:34.427Z] 20:51:34 INFO - 1568062294425 Marionette DEBUG 73 <- [1,3,null,{"value":null}]
[task 2019-09-09T20:51:34.427Z] 20:51:34 INFO - 1568062294426 Marionette DEBUG 73 -> [0,4,"WebDriver:SetTimeouts",{"implicit":0}]
[task 2019-09-09T20:51:34.429Z] 20:51:34 INFO - 1568062294426 Marionette DEBUG 73 <- [1,4,null,{"value":null}]
[task 2019-09-09T20:51:34.432Z] 20:51:34 INFO - 1568062294429 Marionette DEBUG 73 -> [0,5,"WebDriver:DeleteSession",{}]
[task 2019-09-09T20:51:34.432Z] 20:51:34 INFO - 1568062294430 Marionette DEBUG 73 <- [1,5,null,{"value":null}]
[task 2019-09-09T20:51:34.436Z] 20:51:34 INFO - 1568062294434 Marionette DEBUG Accepted connection 74 from 127.0.0.1:59492
[task 2019-09-09T20:51:34.436Z] 20:51:34 INFO - 1568062294435 Marionette DEBUG Closed connection 73
[task 2019-09-09T20:51:34.440Z] 20:51:34 INFO - 1568062294438 Marionette DEBUG 74 -> [0,1,"WebDriver:NewSession",{"moz:useNonSpecCompliantPointerOrigin":true}]
[task 2019-09-09T20:51:34.441Z] 20:51:34 INFO - 1568062294439 Marionette TRACE [5] Frame script loaded
[task 2019-09-09T20:51:34.443Z] 20:51:34 INFO - 1568062294440 Marionette TRACE [5] Frame script registered
[task 2019-09-09T20:51:34.444Z] 20:51:34 INFO - 1568062294442 Marionette DEBUG 74 <- [1,1,null,{"sessionId":"34e2eb5e-eb68-4793-bbbe-f2c156300a37","capabilities":{"browserName":"firefox","browserVersion":"71.0a ... tmp/tmpYxRbR0.mozrunner","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":true,"moz:webdriverClick":true}}]
[task 2019-09-09T20:51:34.445Z] 20:51:34 INFO - 1568062294444 Marionette DEBUG 74 -> [0,2,"WebDriver:Navigate",{"url":"data:text/html;charset=utf-8,%0A%20%20%20%20%20%20%20%20%20%20%3Cdiv%20id%3D%22div%22%20sty ... k%3D%22window.click_x%20%3D%20event.clientX%3B%20window.click_y%20%3D%20event.clientY%22%20/%3E%0A%20%20%20%20%20%20%20%20"}]
[task 2019-09-09T20:51:34.453Z] 20:51:34 INFO - 1568062294448 Marionette TRACE [5] Received DOM event beforeunload for http://127.0.0.1:46224/keyboard.html
[task 2019-09-09T20:51:34.453Z] 20:51:34 INFO - 1568062294450 Marionette TRACE [5] Received DOM event pagehide for http://127.0.0.1:46224/keyboard.html
[task 2019-09-09T20:51:34.456Z] 20:51:34 INFO - 1568062294454 Marionette TRACE [5] Received DOM event unload for http://127.0.0.1:46224/keyboard.html
[task 2019-09-09T20:51:34.464Z] 20:51:34 INFO - 1568062294460 Marionette TRACE [5] Received DOM event DOMContentLoaded for data:text/html;charset=utf-8,%0A%20%20%20%20%20%20%20%20%20%20%3Cdiv%20id%3D%22div%22%20style%3D%22width%3A%20150vw%3B%20heig ... lick%3D%22window.click_x%20%3D%20event.clientX%3B%20window.click_y%20%3D%20event.clientY%22%20/%3E%0A%20%20%20%20%20%20%20%20
[task 2019-09-09T20:51:34.484Z] 20:51:34 INFO - 1568062294483 Marionette TRACE [5] Received DOM event pageshow for data:text/html;charset=utf-8,%0A%20%20%20%20%20%20%20%20%20%20%3Cdiv%20id%3D%22div%22%20style%3D%22width%3A%20150vw%3B%20heig ... lick%3D%22window.click_x%20%3D%20event.clientX%3B%20window.click_y%20%3D%20event.clientY%22%20/%3E%0A%20%20%20%20%20%20%20%20
[task 2019-09-09T20:51:34.500Z] 20:51:34 INFO - 1568062294492 Marionette DEBUG 74 <- [1,2,null,{"value":null}]
[task 2019-09-09T20:51:34.500Z] 20:51:34 INFO - 1568062294497 Marionette DEBUG 74 -> [0,3,"WebDriver:FindElement",{"using":"id","value":"div"}]
[task 2019-09-09T20:51:34.507Z] 20:51:34 INFO - 1568062294507 Marionette DEBUG 74 <- [1,3,null,{"value":{"element-6066-11e4-a52e-4f735466cecf":"8d76d149-8c6e-4965-92c4-9b20ee17b145"}}]
[task 2019-09-09T20:51:34.511Z] 20:51:34 INFO - 1568062294509 Marionette DEBUG 74 -> [0,4,"WebDriver:GetElementRect",{"id":"8d76d149-8c6e-4965-92c4-9b20ee17b145"}]
[task 2019-09-09T20:51:34.514Z] 20:51:34 INFO - 1568062294512 Marionette DEBUG 74 <- [1,4,null,{"x":8,"y":8,"width":1920,"height":1449}]
[task 2019-09-09T20:51:34.515Z] 20:51:34 INFO - 1568062294513 Marionette DEBUG 74 -> [0,5,"WebDriver:GetElementRect",{"id":"8d76d149-8c6e-4965-92c4-9b20ee17b145"}]
[task 2019-09-09T20:51:34.516Z] 20:51:34 INFO - 1568062294514 Marionette DEBUG 74 <- [1,5,null,{"x":8,"y":8,"width":1920,"height":1449}]
[task 2019-09-09T20:51:34.517Z] 20:51:34 INFO - 1568062294515 Marionette DEBUG 74 -> [0,6,"WebDriver:GetElementRect",{"id":"8d76d149-8c6e-4965-92c4-9b20ee17b145"}]
[task 2019-09-09T20:51:34.521Z] 20:51:34 INFO - 1568062294517 Marionette DEBUG 74 <- [1,6,null,{"x":8,"y":8,"width":1920,"height":1449}]
[task 2019-09-09T20:51:34.521Z] 20:51:34 INFO - 1568062294519 Marionette DEBUG 74 -> [0,7,"WebDriver:GetElementRect",{"id":"8d76d149-8c6e-4965-92c4-9b20ee17b145"}]
[task 2019-09-09T20:51:34.521Z] 20:51:34 INFO - 1568062294520 Marionette DEBUG 74 <- [1,7,null,{"x":8,"y":8,"width":1920,"height":1449}]
[task 2019-09-09T20:51:34.524Z] 20:51:34 INFO - 1568062294520 Marionette DEBUG 74 -> [0,8,"WebDriver:PerformActions",{"actions":[{"parameters":{"pointerType":"mouse"},"type":"pointer","id":"pointer_id","actions ... 4f735466cecf":"8d76d149-8c6e-4965-92c4-9b20ee17b145"}},{"button":0,"type":"pointerDown"},{"button":0,"type":"pointerUp"}]}]}]
[task 2019-09-09T20:51:34.531Z] 20:51:34 INFO - 1568062294529 Marionette DEBUG 74 <- [1,8,null,{"value":null}]
[task 2019-09-09T20:51:34.532Z] 20:51:34 INFO - 1568062294530 Marionette DEBUG 74 -> [0,9,"WebDriver:ExecuteScript",{"script":"if (window.click_x && window.click_y) {\n return {x: window.click_x, y: ... ],"filename":"tests/testing/marionette/harness/marionette_harness/tests/unit/test_mouse_action.py","sandbox":null,"line":42}]
[task 2019-09-09T20:51:34.540Z] 20:51:34 INFO - 1568062294534 Marionette DEBUG 74 <- [1,9,null,{"value":{"x":968,"y":733}}]
[task 2019-09-09T20:51:34.540Z] 20:51:34 INFO - 1568062294535 Marionette DEBUG 74 -> [0,10,"WebDriver:DeleteSession",{}]
[task 2019-09-09T20:51:34.541Z] 20:51:34 INFO - 1568062294536 Marionette DEBUG 74 <- [1,10,null,{"value":null}]
[task 2019-09-09T20:51:34.542Z] 20:51:34 INFO - 1568062294538 Marionette DEBUG Closed connection 74
[task 2019-09-09T20:51:34.542Z] 20:51:34 INFO - 1568062294538 Marionette DEBUG Accepted connection 75 from 127.0.0.1:59494
[task 2019-09-09T20:51:34.543Z] 20:51:34 INFO - 1568062294539 Marionette DEBUG 75 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
[task 2019-09-09T20:51:34.551Z] 20:51:34 INFO - 1568062294546 Marionette TRACE [5] Frame script loaded
[task 2019-09-09T20:51:34.551Z] 20:51:34 INFO - 1568062294546 Marionette TRACE [5] Frame script registered
[task 2019-09-09T20:51:34.551Z] 20:51:34 INFO - 1568062294547 Marionette DEBUG 75 <- [1,1,null,{"sessionId":"379bdb83-3f84-4a85-b67d-71ece1741f12","capabilities":{"browserName":"firefox","browserVersion":"71.0a ... mp/tmpYxRbR0.mozrunner","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true}}]
[task 2019-09-09T20:51:34.552Z] 20:51:34 INFO - 1568062294548 Marionette DEBUG 75 -> [0,2,"WebDriver:ReleaseActions",{}]
[task 2019-09-09T20:51:34.552Z] 20:51:34 INFO - 1568062294549 Marionette DEBUG 75 <- [1,2,null,{"value":null}]
[task 2019-09-09T20:51:34.555Z] 20:51:34 INFO - 1568062294549 Marionette DEBUG 75 -> [0,3,"WebDriver:DeleteSession",{}]
[task 2019-09-09T20:51:34.555Z] 20:51:34 INFO - TEST-PASS | testing/marionette/harness/marionette_harness/tests/unit/test_mouse_action.py TestNonSpecCompliantPointerOrigin.test_click_element_larger_than_viewport_with_center_point_inside | took 144ms
[task 2019-09-09T20:51:34.555Z] 20:51:34 INFO - TEST-START | testing/marionette/harness/marionette_harness/tests/unit/test_mouse_action.py

Comment 1

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

Problem here seems to be that the context menu (contentAreaContextMenu) doesn't open with the issued right click. Maja did most of the work here, so maybe she can remember what might be the cause.

How often does that failure happen?

Comment 2

[Edwin Takahashi (:egao | infrequent contributor)]

:whimboo - I'm investigating if this is a permanent failure on debian 10, or if intermittent. I recall in some test runs this failure was not observed, and the Debian 10 test image is still in a state of flux, which is why I suspect it may possibly be the way it is configured.

Comment 3

[Edwin Takahashi (:egao | infrequent contributor)]

In the recent pushes, it seems to be a permafail on Debian 10: https://treeherder.mozilla.org/#/jobs?repo=try&group_state=expanded&revision=cb86b15c5fc0f1d70991d5f7b716e985d4066690 and https://treeherder.mozilla.org/#/jobs?repo=try&group_state=expanded&revision=26a994e45455bb67e1ce51b44c0e6a45d3546bcf.

But on an older push the test passes: https://treeherder.mozilla.org/#/jobs?repo=try&group_state=expanded&searchStr=marionette&revision=94fa4a85d50c81e7fd898ead492c6f5de6b83524

The difference is in how and where pulseaudio is initialized - perhaps this marionette test relies on pulseaudio being initialized?

Comment 4

[Edwin Takahashi (:egao | infrequent contributor)]

I pushed another try run, this time explicitly initializing pulseaudio in the marionette.py mozharness script.

Push: https://treeherder.mozilla.org/#/jobs?repo=try&revision=fc48ec6a00589aa2f1a06be7668aed993643bb5d

It seems the explicit instantiation of pulseaudio did not resolve the issue, so something else must be causing the failure.

Comment 5

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

I don't see why pulseaudio should make a difference here. It's more related to the fact that a right mouse click doesn't open the context menu.

Comment 6

[Edwin Takahashi (:egao | infrequent contributor)]

I didn't think it would be pulseaudio, but I wanted to be absolutely sure, since the failure started happening within the last week or so, and the Debian 10 related work is still very much in flux.

Comment 7

[Intermittent Failures Robot]

1 failures in 4637 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• try: 1

Platform breakdown:

• linux64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1580401&startday=2019-09-09&endday=2019-09-15&tree=all

Comment 8

[Edwin Takahashi (:egao | infrequent contributor)]

Failure message on this test has changed with the most recent try push:

testing/marionette/harness/marionette_harness/tests/unit/test_mouse_action.py TestPointerActions.test_context_click_action | TimeoutException: Timed out after 5.0 seconds with message: Context menu did not open

Failure log: https://taskcluster-artifacts.net/CJ-y3D6fSzSFW6Pk9QIczg/0/public/logs/live_backing.log
Try: https://treeherder.mozilla.org/#/jobs?repo=try&group_state=expanded&selectedJob=271357339&revision=eaedcbe3ff8defa9b57039efe3acd405e02de1f3
Marionette report: https://taskcluster-artifacts.net/CJ-y3D6fSzSFW6Pk9QIczg/0/public/test_info//report.html

Comment 9

[Geoff Brown [:gbrown]]

It looks to me like this may be the only marionette test with a right click (click() with button=2). I wonder if this Debian environment supports right click; maybe there is a mouse preference that could be modified?

Comment 10

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

Yes, since bug 1354458 has been fixed we have more details about the underlying reason of the timeout. Updating the summary now to reflect that.

Comment 11

[Edwin Takahashi (:egao | infrequent contributor)]

I wonder if this bug or marionette in general relates to the other input issues I'm seeing, such as bug 1580013 (arrowkey-down not firing) and a bunch of InvalidArgumentException: Unknown pointerType: [object String] "touch" issues in wpt that was tracked by now-closed bug 1562167.

I think there might be something with the way Debian pointers interact with marionette that might be causing all this.

Comment 12

[Edwin Takahashi (:egao | infrequent contributor)]

:jgraham mentioned that the InvalidArgumentException: Unknown pointerType failure is a known issue with gecko, documented in bug 1543337.

Comment 13

[Intermittent Failures Robot]

1 failures in 4314 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• try: 1

Platform breakdown:

• linux64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1580401&startday=2019-10-28&endday=2019-11-03&tree=all

Comment 14

[Edwin Takahashi (:egao | infrequent contributor)]

Closing this bug as debian10 path is no longer pursued; instead work is being focused on ubuntu1804 as the future distro for linux CI.