Closed
Bug 1716873
Opened 4 years ago
Closed 4 years ago
Intermittent testing/marionette/harness/marionette_harness/tests/unit/test_mouse_action.py TestPointerActions.test_context_click_action | OSError: Process killed because the connection to Marionette server is lost. Check gecko.log for errors (Reason: Conn
Categories
(Testing :: Marionette Client and Harness, defect, P5)
Testing
Marionette Client and Harness
Tracking
(Not tracked)
RESOLVED
INCOMPLETE
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=342993110&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/XZOUKPbgQHOuvn-s9SQ2OA/runs/0/artifacts/public/logs/live_backing.log
[task 2021-06-16T19:51:00.273Z] 19:51:00 INFO - TEST-START | testing/marionette/harness/marionette_harness/tests/unit/test_mouse_action.py TestPointerActions.test_context_click_action
[task 2021-06-16T19:51:00.273Z] 19:51:00 INFO - 1623873060271 Marionette DEBUG Closed connection 77
[task 2021-06-16T19:51:00.274Z] 19:51:00 INFO - 1623873060272 Marionette DEBUG Accepted connection 78 from 127.0.0.1:46084
[task 2021-06-16T19:51:00.279Z] 19:51:00 INFO - 1623873060278 Marionette DEBUG 78 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
[task 2021-06-16T19:51:00.283Z] 19:51:00 INFO - 1623873060282 Marionette DEBUG 78 <- [1,1,null,{"sessionId":"05008984-b333-40bb-8092-1f57ae745988","capabilities":{"browserName":"firefox","browserVersion":"91.0a ... .mozrunner","moz:shutdownTimeout":300000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true,"proxy":{}}}]
[task 2021-06-16T19:51:00.286Z] 19:51:00 INFO - 1623873060286 Marionette DEBUG 78 -> [0,2,"WebDriver:SetTimeouts",{"script":30000}]
[task 2021-06-16T19:51:00.287Z] 19:51:00 INFO - 1623873060286 Marionette DEBUG 78 <- [1,2,null,{"value":null}]
[task 2021-06-16T19:51:00.288Z] 19:51:00 INFO - 1623873060288 Marionette DEBUG 78 -> [0,3,"WebDriver:SetTimeouts",{"pageLoad":300000}]
[task 2021-06-16T19:51:00.289Z] 19:51:00 INFO - 1623873060288 Marionette DEBUG 78 <- [1,3,null,{"value":null}]
[task 2021-06-16T19:51:00.290Z] 19:51:00 INFO - 1623873060290 Marionette DEBUG 78 -> [0,4,"WebDriver:SetTimeouts",{"implicit":0}]
[task 2021-06-16T19:51:00.291Z] 19:51:00 INFO - 1623873060290 Marionette DEBUG 78 <- [1,4,null,{"value":null}]
[task 2021-06-16T19:51:00.298Z] 19:51:00 INFO - 1623873060298 Marionette DEBUG 78 -> [0,5,"WebDriver:Navigate",{"url":"http://127.0.0.1:42299/clicks.html"}]
[task 2021-06-16T19:51:00.303Z] 19:51:00 INFO - 1623873060301 Marionette TRACE [28] MarionetteEvents actor created for window id 2147483667
[task 2021-06-16T19:51:00.305Z] 19:51:00 INFO - 1623873060304 Marionette TRACE [28] Received event beforeunload for data:text/html;charset=utf-8,%0A%20%20%20%20%20%20%20%20%20%20%20%20%3Cdiv%20style%3D%22position%3Arelative%3Btop%3A200vh%3B%22%3Efoo%3C/div%3E%0A%20%20%20%20%20%20%20%20
[task 2021-06-16T19:51:00.335Z] 19:51:00 INFO - 1623873060335 Marionette TRACE [28] Received event pagehide for data:text/html;charset=utf-8,%0A%20%20%20%20%20%20%20%20%20%20%20%20%3Cdiv%20style%3D%22position%3Arelative%3Btop%3A200vh%3B%22%3Efoo%3C/div%3E%0A%20%20%20%20%20%20%20%20
[task 2021-06-16T19:51:00.379Z] 19:51:00 INFO - 1623873060376 Marionette TRACE [28] MarionetteEvents actor created for window id 2147483668
[task 2021-06-16T19:51:00.406Z] 19:51:00 INFO - 1623873060405 Marionette TRACE [28] Received event DOMContentLoaded for http://127.0.0.1:42299/clicks.html
[task 2021-06-16T19:51:00.407Z] 19:51:00 INFO - 1623873060406 Marionette TRACE [28] Received event pageshow for http://127.0.0.1:42299/clicks.html
[task 2021-06-16T19:51:00.410Z] 19:51:00 INFO - 1623873060409 Marionette DEBUG 78 <- [1,5,null,{"value":null}]
[task 2021-06-16T19:51:00.442Z] 19:51:00 INFO - 1623873060441 Marionette DEBUG 78 -> [0,6,"WebDriver:FindElement",{"value":"normal","using":"id"}]
[task 2021-06-16T19:51:00.447Z] 19:51:00 INFO - 1623873060446 Marionette TRACE [28] MarionetteCommands actor created for window id 2147483668
[task 2021-06-16T19:51:00.455Z] 19:51:00 INFO - 1623873060454 Marionette DEBUG 78 <- [1,6,null,{"value":{"element-6066-11e4-a52e-4f735466cecf":"cdb6ec7d-790a-428d-86bb-26f71a45a36e"}}]
[task 2021-06-16T19:51:00.457Z] 19:51:00 INFO - 1623873060456 Marionette DEBUG 78 -> [0,7,"Marionette:GetContext",{}]
[task 2021-06-16T19:51:00.460Z] 19:51:00 INFO - 1623873060457 Marionette DEBUG 78 <- [1,7,null,{"value":"content"}]
[task 2021-06-16T19:51:00.468Z] 19:51:00 INFO - 1623873060467 Marionette DEBUG 78 -> [0,8,"Marionette:SetContext",{"value":"chrome"}]
[task 2021-06-16T19:51:00.468Z] 19:51:00 INFO - 1623873060467 Marionette DEBUG 78 <- [1,8,null,{"value":null}]
[task 2021-06-16T19:51:00.470Z] 19:51:00 INFO - 1623873060470 Marionette DEBUG 78 -> [0,9,"WebDriver:FindElement",{"value":"contentAreaContextMenu","using":"id"}]
[task 2021-06-16T19:51:00.471Z] 19:51:00 INFO - 1623873060471 Marionette TRACE [1] MarionetteCommands actor created for window id 2
[task 2021-06-16T19:51:00.475Z] 19:51:00 INFO - 1623873060475 Marionette DEBUG 78 <- [1,9,null,{"value":{"element-6066-11e4-a52e-4f735466cecf":"46315085-7b4c-4730-b684-c58c669ff87b"}}]
[task 2021-06-16T19:51:00.480Z] 19:51:00 INFO - 1623873060479 Marionette DEBUG 78 -> [0,10,"WebDriver:GetElementProperty",{"id":"46315085-7b4c-4730-b684-c58c669ff87b","name":"state"}]
[task 2021-06-16T19:51:00.482Z] 19:51:00 INFO - 1623873060482 Marionette DEBUG 78 <- [1,10,null,{"value":"closed"}]
[task 2021-06-16T19:51:00.484Z] 19:51:00 INFO - 1623873060483 Marionette DEBUG 78 -> [0,11,"Marionette:SetContext",{"value":"content"}]
[task 2021-06-16T19:51:00.484Z] 19:51:00 INFO - 1623873060484 Marionette DEBUG 78 <- [1,11,null,{"value":null}]
[task 2021-06-16T19:51:00.486Z] 19:51:00 INFO - 1623873060485 Marionette DEBUG 78 -> [0,12,"WebDriver:PerformActions",{"actions":[{"type":"pointer","id":"pointer_id","actions":[{"type":"pointerMove","x":0,"y":0 ... b-26f71a45a36e"}},{"type":"pointerDown","button":2},{"type":"pointerUp","button":2}],"parameters":{"pointerType":"mouse"}}]}]
[task 2021-06-16T19:51:00.553Z] 19:51:00 INFO - DEBUG: Adding blocker UserInteractionTimer 9 for document 61e0000ea080 for phase xpcom-will-shutdown
[task 2021-06-16T20:02:11.737Z] 20:02:11 INFO - TEST-UNEXPECTED-ERROR | testing/marionette/harness/marionette_harness/tests/unit/test_mouse_action.py TestPointerActions.test_context_click_action | OSError: Process killed because the connection to Marionette server is lost. Check gecko.log for errors (Reason: Connection timed out after 360.0s)
[task 2021-06-16T20:02:11.738Z] 20:02:11 INFO - Traceback (most recent call last):
[task 2021-06-16T20:02:11.738Z] 20:02:11 INFO - File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_harness/marionette_test/testcases.py", line 214, in run
[task 2021-06-16T20:02:11.738Z] 20:02:11 INFO - testMethod()
[task 2021-06-16T20:02:11.739Z] 20:02:11 INFO - File "/builds/worker/workspace/build/tests/marionette/tests/testing/marionette/harness/marionette_harness/tests/unit/test_mouse_action.py", line 109, in test_context_click_action
[task 2021-06-16T20:02:11.739Z] 20:02:11 INFO - self.mouse_chain.click(element=click_el, button=2).perform()
[task 2021-06-16T20:02:11.739Z] 20:02:11 INFO - File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_driver/marionette.py", line 76, in perform
[task 2021-06-16T20:02:11.739Z] 20:02:11 INFO - self.marionette.actions.perform([self.dict])
[task 2021-06-16T20:02:11.739Z] 20:02:11 INFO - File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_driver/marionette.py", line 180, in perform
[task 2021-06-16T20:02:11.740Z] 20:02:11 INFO - return self.marionette._send_message("WebDriver:PerformActions", body)
[task 2021-06-16T20:02:11.740Z] 20:02:11 INFO - File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_driver/decorators.py", line 37, in _
[task 2021-06-16T20:02:11.740Z] 20:02:11 INFO - m._handle_socket_failure()
[task 2021-06-16T20:02:11.741Z] 20:02:11 INFO - File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_driver/marionette.py", line 716, in _handle_socket_failure
[task 2021-06-16T20:02:11.741Z] 20:02:11 INFO - IOError, IOError(message.format(returncode=returncode, reason=exc)), tb
[task 2021-06-16T20:02:11.741Z] 20:02:11 INFO - File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/six.py", line 702, in reraise
[task 2021-06-16T20:02:11.741Z] 20:02:11 INFO - raise value.with_traceback(tb)
[task 2021-06-16T20:02:11.741Z] 20:02:11 INFO - File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_driver/decorators.py", line 27, in _
[task 2021-06-16T20:02:11.741Z] 20:02:11 INFO - return func(*args, **kwargs)
[task 2021-06-16T20:02:11.741Z] 20:02:11 INFO - File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_driver/marionette.py", line 621, in _send_message
[task 2021-06-16T20:02:11.741Z] 20:02:11 INFO - msg = self.client.request(name, params)
[task 2021-06-16T20:02:11.741Z] 20:02:11 INFO - File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_driver/transport.py", line 292, in request
[task 2021-06-16T20:02:11.742Z] 20:02:11 INFO - return self.receive()
[task 2021-06-16T20:02:11.742Z] 20:02:11 INFO - File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_driver/transport.py", line 196, in receive
[task 2021-06-16T20:02:11.742Z] 20:02:11 INFO - "Connection timed out after {}s".format(self.socket_timeout)
[task 2021-06-16T20:02:11.742Z] 20:02:11 INFO - TEST-INFO took 671463ms
[task 2021-06-16T20:02:11.745Z] 20:02:11 ERROR - test_end for testing/marionette/harness/marionette_harness/tests/unit/test_mouse_action.py TestPointerActions.test_context_click_action logged while not in progress. Logged with data: {"message": "marionette_driver.errors.InvalidSessionIdException: Please start a session", "expected": "PASS", "stack": "Traceback (most recent call last):\n File \"/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_harness/marionette_test/testcases.py\", line 247, in run\n self.tearDown()\n File \"/builds/worker/workspace/build/tests/marionette/tests/testing/marionette/harness/marionette_harness/tests/unit/test_mouse_action.py\", line 32, in tearDown\n self.marionette.actions.release()\n File \"/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_driver/marionette.py\", line 183, in release\n return self.marionette._send_message(\"WebDriver:ReleaseActions\")\n File \"/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_driver/decorators.py\", line 27, in _\n return func(*args, **kwargs)\n File \"/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_driver/marionette.py\", line 618, in _send_message\n raise errors.InvalidSessionIdException(\"Please start a session\")\n", "extra": {"class_name": "test_mouse_action.TestPointerActions", "method_name": "test_context_click_action"}, "test": "testing/marionette/harness/marionette_harness/tests/unit/test_mouse_action.py TestPointerActions.test_context_click_action", "status": "ERROR"}
| Comment hidden (Intermittent Failures Robot) |
|
||
Comment 2•4 years ago
|
||
We might need more logging in action code to figure out what caused the hang. But with a single instance of the crash so far it's not worth it for the time being:
[task 2021-06-16T19:51:00.486Z] 19:51:00 INFO - 1623873060485 Marionette DEBUG 78 -> [0,12,"WebDriver:PerformActions",{"actions":[{"type":"pointer","id":"pointer_id","actions":[{"type":"pointerMove","x":0,"y":0 ... b-26f71a45a36e"}},{"type":"pointerDown","button":2},{"type":"pointerUp","button":2}],"parameters":{"pointerType":"mouse"}}]}]
[task 2021-06-16T19:51:00.553Z] 19:51:00 INFO - DEBUG: Adding blocker UserInteractionTimer 9 for document 61e0000ea080 for phase xpcom-will-shutdown
|
||
Comment 3•4 years ago
|
||
https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.
Status: NEW → RESOLVED
Closed: 4 years ago
Resolution: --- → INCOMPLETE
|
||
Comment 4•4 years ago
|
||
Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=346113978&repo=mozilla-central&lineNumber=32006
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
| Comment hidden (Intermittent Failures Robot) |
|
|
||
Comment 6•4 years ago
|
||
https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.
Status: REOPENED → RESOLVED
Closed: 4 years ago → 4 years ago
Resolution: --- → INCOMPLETE
|
||
Updated•3 years ago
|
Product: Testing → Remote Protocol
|
|
||
Comment 7•3 years ago
|
||
Moving bug to Testing::Marionette Client and Harness component per bug 1815831.
Component: Marionette → Marionette Client and Harness
Product: Remote Protocol → Testing
You need to log in
before you can comment on or make changes to this bug.
Description
•