1641832 - Intermittent telemetry/marionette/tests/client/test_subsession_management.py TestSubsessionManagement.test_subsession_management | IOError: Process killed because the connection to Marionette server is lost. Check gecko.log for errors (Reason: [Errno 1005

Status: RESOLVED INCOMPLETE

(Toolkit :: Telemetry, defect, P5)

Description

[Treeherder Bug Filer]

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

---

...
[task 2020-05-29T10:29:22.358Z] 10:29:22     INFO - pingserver pings_handler received 'main' ping with reason 'shutdown'
[task 2020-05-29T10:29:22.365Z] 10:29:22     INFO -  1590748162360	Toolkit.Telemetry	INFO	TelemetrySend::_doPing - successfully loaded, status: 200
[task 2020-05-29T10:29:22.365Z] 10:29:22     INFO -  1590748162360	Toolkit.Telemetry	TRACE	TelemetrySend::_onPingRequestFinished - success: true, persisted: true
[task 2020-05-29T10:29:22.365Z] 10:29:22     INFO -  1590748162360	Toolkit.Telemetry	TRACE	TelemetryStorage::removePendingPing - deleting ping with id: 44255422-640b-4acb-9c84-264b3c0fe013, path: Z:\task_1590747674\build\tmpjifqa1.mozrunner\saved-telemetry-pings\44255422-640b-4acb-9c84-264b3c0fe013
[task 2020-05-29T10:29:22.392Z] 10:29:22     INFO -  1590748162387	Toolkit.Telemetry	TRACE	TelemetrySend::Scheduler::_doSendTask - bailing out after sending, shutdown: false, pendingPingCount: 0
[task 2020-05-29T10:29:22.411Z] 10:29:22     INFO -  ###!!! ERROR: Potential deadlock detected:
[task 2020-05-29T10:29:22.411Z] 10:29:22     INFO -  === Cyclical dependency starts at
[task 2020-05-29T10:29:22.412Z] 10:29:22     INFO -  --- Mutex : StaticMutex (currently acquired)
[task 2020-05-29T10:29:22.412Z] 10:29:22     INFO -   calling context
[task 2020-05-29T10:29:22.413Z] 10:29:22     INFO -    [stack trace unavailable]
[task 2020-05-29T10:29:22.413Z] 10:29:22     INFO -  === Cycle completed at
[task 2020-05-29T10:29:22.413Z] 10:29:22     INFO -  --- Mutex : StaticMutex (currently acquired)
[task 2020-05-29T10:29:22.413Z] 10:29:22     INFO -   calling context
[task 2020-05-29T10:29:22.413Z] 10:29:22     INFO -    [stack trace unavailable]
[task 2020-05-29T10:29:22.413Z] 10:29:22     INFO -  ###!!! Deadlock may happen NOW!
[task 2020-05-29T10:29:22.413Z] 10:29:22     INFO -  [Parent 4452, Main Thread] ###!!! ASSERTION: Potential deadlock detected:
[task 2020-05-29T10:29:22.413Z] 10:29:22     INFO -  Cyclical dependency starts at
[task 2020-05-29T10:29:22.414Z] 10:29:22     INFO -  Mutex : StaticMutex (currently acquired)
[task 2020-05-29T10:29:22.414Z] 10:29:22     INFO -  Cycle completed at
[task 2020-05-29T10:29:22.414Z] 10:29:22     INFO -  Mutex : StaticMutex (currently acquired)
[task 2020-05-29T10:29:22.414Z] 10:29:22     INFO -  ###!!! Deadlock may happen NOW!
[task 2020-05-29T10:29:22.414Z] 10:29:22     INFO -  : 'Error', file /builds/worker/checkouts/gecko/xpcom/threads/BlockingResourceBase.cpp, line 248
[task 2020-05-29T10:31:35.695Z] 10:31:35     INFO -  Exiting due to channel error.
[task 2020-05-29T10:31:35.695Z] 10:31:35     INFO -  Exiting due to channel error.
[task 2020-05-29T10:31:36.035Z] 10:31:36     INFO - TEST-UNEXPECTED-ERROR | telemetry/marionette/tests/client/test_subsession_management.py TestSubsessionManagement.test_subsession_management | IOError: Process killed because the connection to Marionette server is lost. Check gecko.log for errors (Reason: [Errno 10053] An established connection was aborted by the software in your host machine)
[task 2020-05-29T10:31:36.035Z] 10:31:36     INFO - Traceback (most recent call last):
[task 2020-05-29T10:31:36.035Z] 10:31:36     INFO -   File "Z:\task_1590747674\build\venv\lib\site-packages\marionette_harness\marionette_test\testcases.py", line 191, in run
[task 2020-05-29T10:31:36.035Z] 10:31:36     INFO -     testMethod()
[task 2020-05-29T10:31:36.035Z] 10:31:36     INFO -   File "Z:\task_1590747674\build\tests\telemetry\marionette\tests\client\test_subsession_management.py", line 29, in test_subsession_management
[task 2020-05-29T10:31:36.035Z] 10:31:36     INFO -     ping1 = self.wait_for_ping(self.restart_browser, MAIN_SHUTDOWN_PING)
[task 2020-05-29T10:31:36.035Z] 10:31:36     INFO -   File "Z:\task_1590747674\build\venv\lib\site-packages\telemetry_harness\testcase.py", line 149, in wait_for_ping
[task 2020-05-29T10:31:36.035Z] 10:31:36     INFO -     [ping] = self.wait_for_pings(action_func, ping_filter, 1)
[task 2020-05-29T10:31:36.035Z] 10:31:36     INFO -   File "Z:\task_1590747674\build\venv\lib\site-packages\telemetry_harness\testcase.py", line 136, in wait_for_pings
[task 2020-05-29T10:31:36.036Z] 10:31:36     INFO -     action_func()
[task 2020-05-29T10:31:36.036Z] 10:31:36     INFO -   File "Z:\task_1590747674\build\venv\lib\site-packages\telemetry_harness\testcase.py", line 154, in restart_browser
[task 2020-05-29T10:31:36.036Z] 10:31:36     INFO -     return self.marionette.restart(clean=False, in_app=True)
[task 2020-05-29T10:31:36.036Z] 10:31:36     INFO -   File "Z:\task_1590747674\build\venv\lib\site-packages\marionette_driver\decorators.py", line 36, in _
[task 2020-05-29T10:31:36.036Z] 10:31:36     INFO -     m._handle_socket_failure()
[task 2020-05-29T10:31:36.036Z] 10:31:36     INFO -   File "Z:\task_1590747674\build\venv\lib\site-packages\marionette_driver\marionette.py", line 682, in _handle_socket_failure
[task 2020-05-29T10:31:36.036Z] 10:31:36     INFO -     reraise(IOError, IOError(message.format(returncode=returncode, reason=exc)), tb)
[task 2020-05-29T10:31:36.036Z] 10:31:36     INFO -   File "Z:\task_1590747674\build\venv\lib\site-packages\marionette_driver\decorators.py", line 26, in _
[task 2020-05-29T10:31:36.036Z] 10:31:36     INFO -     return func(*args, **kwargs)
[task 2020-05-29T10:31:36.036Z] 10:31:36     INFO -   File "Z:\task_1590747674\build\venv\lib\site-packages\marionette_driver\marionette.py", line 1037, in restart
[task 2020-05-29T10:31:36.036Z] 10:31:36     INFO -     self._send_message("Marionette:AcceptConnections", {"value": True})
[task 2020-05-29T10:31:36.036Z] 10:31:36     INFO -   File "Z:\task_1590747674\build\venv\lib\site-packages\marionette_driver\decorators.py", line 26, in _
[task 2020-05-29T10:31:36.036Z] 10:31:36     INFO -     return func(*args, **kwargs)
[task 2020-05-29T10:31:36.036Z] 10:31:36     INFO -   File "Z:\task_1590747674\build\venv\lib\site-packages\marionette_driver\marionette.py", line 594, in _send_message
[task 2020-05-29T10:31:36.036Z] 10:31:36     INFO -     msg = self.client.request(name, params)
[task 2020-05-29T10:31:36.036Z] 10:31:36     INFO -   File "Z:\task_1590747674\build\venv\lib\site-packages\marionette_driver\transport.py", line 276, in request
[task 2020-05-29T10:31:36.037Z] 10:31:36     INFO -     return self.receive()
[task 2020-05-29T10:31:36.037Z] 10:31:36     INFO -   File "Z:\task_1590747674\build\venv\lib\site-packages\marionette_driver\transport.py", line 156, in receive
[task 2020-05-29T10:31:36.037Z] 10:31:36     INFO -     chunk = self._sock.recv(bytes_to_recv)
[task 2020-05-29T10:31:36.037Z] 10:31:36     INFO - TEST-INFO took 150543ms
[task 2020-05-29T10:31:36.037Z] 10:31:36    ERROR - test_end for telemetry/marionette/tests/client/test_subsession_management.py TestSubsessionManagement.test_subsession_management logged while not in progress. Logged with data: {"status": "ERROR", "extra": {"class_name": "test_subsession_management.TestSubsessionManagement", "method_name": "test_subsession_management"}, "expected": "PASS", "test": "telemetry/marionette/tests/client/test_subsession_management.py TestSubsessionManagement.test_subsession_management", "message": "InvalidSessionIdException: Please start a session", "stack": "Traceback (most recent call last):\n  File \"Z:\\task_1590747674\\build\\venv\\lib\\site-packages\\marionette_harness\\marionette_test\\testcases.py\", line 222, in run\n    self.tearDown()\n  File \"Z:\\task_1590747674\\build\\venv\\lib\\site-packages\\telemetry_harness\\testcase.py\", line 220, in tearDown\n    super(TelemetryTestCase, self).tearDown()\n  File \"Z:\\task_1590747674\\build\\venv\\lib\\site-packages\\marionette_harness\\runner\\mixins\\window_manager.py\", line 25, in tearDown\n    if len(self.marionette.chrome_window_handles) > len(self.start_windows):\n  File \"Z:\\task_1590747674\\build\\venv\\lib\\site-packages\\marionette_driver\\marionette.py\", line 1261, in chrome_window_handles\n    return self._send_message(\"WebDriver:GetChromeWindowHandles\")\n  File \"Z:\\task_1590747674\\build\\venv\\lib\\site-packages\\marionette_driver\\decorators.py\", line 26, in _\n    return func(*args, **kwargs)\n  File \"Z:\\task_1590747674\\build\\venv\\lib\\site-packages\\marionette_driver\\marionette.py\", line 591, in _send_message\n    raise errors.InvalidSessionIdException(\"Please start a session\")\n"}

Comment 1

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-central: 1

Platform breakdown:

• windows7-32-mingwclang: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1641832&startday=2020-05-25&endday=2020-05-31&tree=all

Comment 2

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

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

Comment 3

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-esr78: 1

Platform breakdown:

• windows10-64-mingwclang: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1641832&startday=2020-06-22&endday=2020-06-28&tree=all

Comment 4

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-esr78: 1

Platform and build breakdown:

• windows7-32-mingwclang: 1
  • debug: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1641832&startday=2021-06-07&endday=2021-06-13&tree=all