1735959 - Intermittent testing/marionette/harness/marionette_harness/tests/unit/test_sendkeys_menupopup_chrome.py TestSendkeysMenupopup.test_sendkeys_hidden_disabled_menuitem | OSError: Process has been unexpectedly closed (Exit code: -5) (Reason: No data received

Status: RESOLVED INCOMPLETE

(Testing :: Marionette Client and Harness, defect, P5)

Description

[Treeherder Bug Filer]

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

---

[task 2021-10-15T02:16:15.518Z] 02:16:15     INFO -  This probably reflects a bug in the program.
[task 2021-10-15T02:16:15.518Z] 02:16:15     INFO -  The error was 'BadMatch (invalid parameter attributes)'.
[task 2021-10-15T02:16:15.519Z] 02:16:15     INFO -    (Details: serial 2892 error_code 8 request_code 73 (core protocol) minor_code 0)
[task 2021-10-15T02:16:15.519Z] 02:16:15     INFO -    (Note to programmers: normally, X errors are reported asynchronously;
[task 2021-10-15T02:16:15.519Z] 02:16:15     INFO -     that is, you will receive the error a while after causing it.
[task 2021-10-15T02:16:15.519Z] 02:16:15     INFO -     To debug your program, run it with the GDK_SYNCHRONIZE environment
[task 2021-10-15T02:16:15.519Z] 02:16:15     INFO -     variable to change this behavior. You can then get a meaningful
[task 2021-10-15T02:16:15.520Z] 02:16:15     INFO -     backtrace from your debugger if you break on the gdk_x_error() function.)
[task 2021-10-15T02:16:15.581Z] 02:16:15     INFO -  Exiting due to channel error.
[task 2021-10-15T02:16:15.581Z] 02:16:15     INFO -  Exiting due to channel error.
[task 2021-10-15T02:16:15.593Z] 02:16:15     INFO -  Exiting due to channel error.
[task 2021-10-15T02:16:15.594Z] 02:16:15     INFO -  Exiting due to channel error.
[task 2021-10-15T02:16:15.640Z] 02:16:15     INFO - TEST-UNEXPECTED-ERROR | testing/marionette/harness/marionette_harness/tests/unit/test_sendkeys_menupopup_chrome.py TestSendkeysMenupopup.test_sendkeys_hidden_disabled_menuitem | OSError: Process has been unexpectedly closed (Exit code: -5) (Reason: No data received over socket)
[task 2021-10-15T02:16:15.640Z] 02:16:15     INFO - Traceback (most recent call last):
[task 2021-10-15T02:16:15.640Z] 02:16:15     INFO -   File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_harness/marionette_test/testcases.py", line 202, in run
[task 2021-10-15T02:16:15.640Z] 02:16:15     INFO -     testMethod()
[task 2021-10-15T02:16:15.641Z] 02:16:15     INFO -   File "/builds/worker/workspace/build/tests/marionette/tests/testing/marionette/harness/marionette_harness/tests/unit/test_sendkeys_menupopup_chrome.py", line 100, in test_sendkeys_hidden_disabled_menuitem
[task 2021-10-15T02:16:15.641Z] 02:16:15     INFO -     self.open_context_menu()
[task 2021-10-15T02:16:15.642Z] 02:16:15     INFO -   File "/builds/worker/workspace/build/tests/marionette/tests/testing/marionette/harness/marionette_harness/tests/unit/test_sendkeys_menupopup_chrome.py", line 50, in open_context_menu
[task 2021-10-15T02:16:15.642Z] 02:16:15     INFO -     attempt_open_context_menu()
[task 2021-10-15T02:16:15.643Z] 02:16:15     INFO -   File "/builds/worker/workspace/build/tests/marionette/tests/testing/marionette/harness/marionette_harness/tests/unit/test_sendkeys_menupopup_chrome.py", line 43, in attempt_open_context_menu
[task 2021-10-15T02:16:15.643Z] 02:16:15     INFO -     self.click_el.click()
[task 2021-10-15T02:16:15.644Z] 02:16:15     INFO -   File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_driver/marionette.py", line 260, in click
[task 2021-10-15T02:16:15.644Z] 02:16:15     INFO -     self.marionette._send_message("WebDriver:ElementClick", {"id": self.id})
[task 2021-10-15T02:16:15.645Z] 02:16:15     INFO -   File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_driver/decorators.py", line 37, in _
[task 2021-10-15T02:16:15.645Z] 02:16:15     INFO -     m._handle_socket_failure()
[task 2021-10-15T02:16:15.646Z] 02:16:15     INFO -   File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_driver/marionette.py", line 717, in _handle_socket_failure
[task 2021-10-15T02:16:15.646Z] 02:16:15     INFO -     IOError, IOError(message.format(returncode=returncode, reason=exc)), tb
[task 2021-10-15T02:16:15.646Z] 02:16:15     INFO -   File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/six.py", line 702, in reraise
[task 2021-10-15T02:16:15.647Z] 02:16:15     INFO -     raise value.with_traceback(tb)
[task 2021-10-15T02:16:15.647Z] 02:16:15     INFO -   File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_driver/decorators.py", line 27, in _
[task 2021-10-15T02:16:15.647Z] 02:16:15     INFO -     return func(*args, **kwargs)
[task 2021-10-15T02:16:15.647Z] 02:16:15     INFO -   File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_driver/marionette.py", line 623, in _send_message
[task 2021-10-15T02:16:15.648Z] 02:16:15     INFO -     msg = self.client.request(name, params)
[task 2021-10-15T02:16:15.648Z] 02:16:15     INFO -   File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_driver/transport.py", line 383, in request
[task 2021-10-15T02:16:15.648Z] 02:16:15     INFO -     return self.receive()
[task 2021-10-15T02:16:15.648Z] 02:16:15     INFO -   File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_driver/transport.py", line 230, in receive
[task 2021-10-15T02:16:15.649Z] 02:16:15     INFO -     raise socket.error("No data received over socket")
[task 2021-10-15T02:16:15.649Z] 02:16:15     INFO - TEST-INFO took 1280ms
[task 2021-10-15T02:16:15.650Z] 02:16:15    ERROR - test_end for testing/marionette/harness/marionette_harness/tests/unit/test_sendkeys_menupopup_chrome.py TestSendkeysMenupopup.test_sendkeys_hidden_disabled_menuitem 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 235, in run\n    self.tearDown()\n  File \"/builds/worker/workspace/build/tests/marionette/tests/testing/marionette/harness/marionette_harness/tests/unit/test_sendkeys_menupopup_chrome.py\", line 67, in tearDown\n    super(TestSendkeysMenupopup, self).tearDown()\n  File \"/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_harness/runner/mixins/window_manager.py\", line 24, in tearDown\n    if len(self.marionette.chrome_window_handles) > len(self.start_windows):\n  File \"/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_driver/marionette.py\", line 1342, in chrome_window_handles\n    with self.using_context(\"chrome\"):\n  File \"/usr/lib/python3.6/contextlib.py\", line 81, in __enter__\n    return next(self.gen)\n  File \"/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_driver/marionette.py\", line 1411, in using_context\n    scope = self._send_message(\"Marionette:GetContext\", key=\"value\")\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 620, in _send_message\n    raise errors.InvalidSessionIdException(\"Please start a session\")\n", "extra": {"class_name": "test_sendkeys_menupopup_chrome.TestSendkeysMenupopup", "method_name": "test_sendkeys_hidden_disabled_menuitem"}, "test": "testing/marionette/harness/marionette_harness/tests/unit/test_sendkeys_menupopup_chrome.py TestSendkeysMenupopup.test_sendkeys_hidden_disabled_menuitem", "status": "ERROR"}

Comment 1

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

The problem here is a X Windows system error as received via GDK:
https://treeherder.mozilla.org/logviewer?job_id=354863072&repo=mozilla-central&lineNumber=70529-70537

[task 2021-10-15T02:16:15.518Z] 02:16:15     INFO -  (firefox:17356): Gdk-ERROR **: 02:16:15.516: The program 'firefox' received an X Window System error.
[task 2021-10-15T02:16:15.518Z] 02:16:15     INFO -  This probably reflects a bug in the program.
[task 2021-10-15T02:16:15.518Z] 02:16:15     INFO -  The error was 'BadMatch (invalid parameter attributes)'.
[task 2021-10-15T02:16:15.519Z] 02:16:15     INFO -    (Details: serial 2892 error_code 8 request_code 73 (core protocol) minor_code 0)
[task 2021-10-15T02:16:15.519Z] 02:16:15     INFO -    (Note to programmers: normally, X errors are reported asynchronously;
[task 2021-10-15T02:16:15.519Z] 02:16:15     INFO -     that is, you will receive the error a while after causing it.
[task 2021-10-15T02:16:15.519Z] 02:16:15     INFO -     To debug your program, run it with the GDK_SYNCHRONIZE environment
[task 2021-10-15T02:16:15.519Z] 02:16:15     INFO -     variable to change this behavior. You can then get a meaningful
[task 2021-10-15T02:16:15.520Z] 02:16:15     INFO -     backtrace from your debugger if you break on the gdk_x_error() function.)

That's a completely new error that I haven't seen ever before. I wonder if some GDK specific changes have been landed recently.

Comment 2

[Karl Tomlinson (:karlt)]

Request code 73 is X_GetImage.

I notice that testing/marionette/harness/marionette_harness/tests/unit/test_reftest.py has recently completed. Perhaps that may perform this operation. I don't know whether or not it might cause any window captures after the test has successfully completed.

I also know of a use in getDisplayMedia() screen capture but can't explain why this code would be active in testing/marionette/harness/marionette_harness/tests/unit/.

Comment 3

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-central: 1

Platform and build breakdown:

• linux1804-64-asan-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1735959&startday=2021-10-11&endday=2021-10-17&tree=all

Comment 4

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

Thank you Karl. Lets observe how often this failure actually happens before doing more investigation. Until now it was a one time only one.

Comment 5

[BugBot [:suhaib / :marco/ :calixte]]

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.

Comment 6

[Sandor Molnar[:smolnar]]

Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=358394847&repo=autoland&lineNumber=44950

Comment 7

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 1

Platform and build breakdown:

• linux1804-64-asan-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1735959&startday=2021-11-15&endday=2021-11-21&tree=all

Comment 8

[BugBot [:suhaib / :marco/ :calixte]]

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.

Comment 9

[BMO Automation]

Moving bug to Testing::Marionette Client and Harness component per bug 1815831.