1633755 - Intermittent telemetry/marionette/tests/unit/test_ping_server_received_ping.py TestPingServer.test_ping_server_received_ping | IOError: Process killed after 120s because no connection to Marionette server could be established. Check gecko.log for errors

Status: RESOLVED INCOMPLETE

(Toolkit :: Telemetry, defect, P5)

Description

[Treeherder Bug Filer]

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

---

task 2020-04-28T04:30:25.407Z] 04:30:25 INFO - 1588048225401 Toolkit.Telemetry INFO TelemetryReportingPolicy::get dataSubmissionPolicyNotifiedDate - No date stored yet.
[task 2020-04-28T04:30:25.422Z] 04:30:25 INFO - 1588048225412 Toolkit.Telemetry TRACE TelemetryStorage::_scanPendingPings
[task 2020-04-28T04:30:25.422Z] 04:30:25 INFO - 1588048225412 Toolkit.Telemetry TRACE TelemetryStorage::_migrateAppDataPings
[task 2020-04-28T04:30:25.422Z] 04:30:25 INFO - 1588048225412 Toolkit.Telemetry TRACE TelemetryStorage::_iterateAppDataPings
[task 2020-04-28T04:30:25.537Z] 04:30:25 INFO - 1588048225529 Toolkit.Telemetry INFO TelemetrySend::_checkPendingPings - pending ping count: 0
[task 2020-04-28T04:30:25.537Z] 04:30:25 INFO - 1588048225529 Toolkit.Telemetry TRACE TelemetrySend::_checkPendingPings - no pending pings
[task 2020-04-28T04:30:25.537Z] 04:30:25 INFO - 1588048225530 Toolkit.Telemetry TRACE TelemetryStorage::_enforcePendingPingsQuota
[task 2020-04-28T04:30:25.538Z] 04:30:25 INFO - 1588048225531 Toolkit.Telemetry TRACE TelemetrySend::Scheduler::triggerSendingPings - active send task: false, immediately: true
[task 2020-04-28T04:30:25.538Z] 04:30:25 INFO - 1588048225531 Toolkit.Telemetry TRACE TelemetrySend::Scheduler::_doSendTask iteration
[task 2020-04-28T04:30:25.538Z] 04:30:25 INFO - 1588048225531 Toolkit.Telemetry TRACE TelemetrySend::Scheduler::_doSendTask - pending: 0, current: 0
[task 2020-04-28T04:30:25.538Z] 04:30:25 INFO - 1588048225531 Toolkit.Telemetry TRACE TelemetrySend::Scheduler::_doSendTask - can send - pending: 0, current: 0
[task 2020-04-28T04:30:25.538Z] 04:30:25 INFO - 1588048225531 Toolkit.Telemetry TRACE TelemetrySend::Scheduler::_doSendTask - no pending pings, bailing out
[task 2020-04-28T04:30:25.539Z] 04:30:25 INFO - 1588048225532 Toolkit.Telemetry TRACE TelemetrySession::delayedInit
[task 2020-04-28T04:30:25.539Z] 04:30:25 INFO - 1588048225532 Toolkit.Telemetry TRACE TelemetryStorage::_popAndPerformQueuedOperation - Performing queued operation.
[task 2020-04-28T04:30:25.539Z] 04:30:25 INFO - 1588048225533 Toolkit.Telemetry INFO TelemetryStorage::_loadSessionData - can not load session data file: {"operation":"open","path":"Z:\task_1588044710\build\tmpgrpget.mozrunner\datareporting\session-state.json","winLastError":2}
[task 2020-04-28T04:30:25.539Z] 04:30:25 INFO - 1588048225534 Toolkit.Telemetry TRACE TelemetryStorage::_popAndPerformQueuedOperation - Performing queued operation.
[task 2020-04-28T04:30:25.575Z] 04:30:25 INFO - 1588048225562 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: signon.importedFromSqlite
[task 2020-04-28T04:30:25.602Z] 04:30:25 INFO - ###!!! ERROR: Potential deadlock detected:
[task 2020-04-28T04:30:25.602Z] 04:30:25 INFO - === Cyclical dependency starts at
[task 2020-04-28T04:30:25.602Z] 04:30:25 INFO - --- Mutex : StaticMutex (currently acquired)
[task 2020-04-28T04:30:25.602Z] 04:30:25 INFO - calling context
[task 2020-04-28T04:30:25.602Z] 04:30:25 INFO - [stack trace unavailable]
[task 2020-04-28T04:30:25.602Z] 04:30:25 INFO - === Cycle completed at
[task 2020-04-28T04:30:25.602Z] 04:30:25 INFO - --- Mutex : StaticMutex (currently acquired)
[task 2020-04-28T04:30:25.602Z] 04:30:25 INFO - calling context
[task 2020-04-28T04:30:25.602Z] 04:30:25 INFO - [stack trace unavailable]
[task 2020-04-28T04:30:25.603Z] 04:30:25 INFO - ###!!! Deadlock may happen NOW!
[task 2020-04-28T04:30:25.603Z] 04:30:25 INFO - [Parent 3548, Main Thread] ###!!! ASSERTION: Potential deadlock detected:
[task 2020-04-28T04:30:25.603Z] 04:30:25 INFO - Cyclical dependency starts at
[task 2020-04-28T04:30:25.603Z] 04:30:25 INFO - Mutex : StaticMutex (currently acquired)
[task 2020-04-28T04:30:25.603Z] 04:30:25 INFO - Cycle completed at
[task 2020-04-28T04:30:25.603Z] 04:30:25 INFO - Mutex : StaticMutex (currently acquired)
[task 2020-04-28T04:30:25.603Z] 04:30:25 INFO - ###!!! Deadlock may happen NOW!
[task 2020-04-28T04:30:25.603Z] 04:30:25 INFO - : 'Error', file /builds/worker/checkouts/gecko/xpcom/threads/BlockingResourceBase.cpp, line 248
[task 2020-04-28T04:32:20.405Z] 04:32:20 INFO - Exiting due to channel error.
[task 2020-04-28T04:32:20.552Z] 04:32:20 INFO - TEST-UNEXPECTED-ERROR | telemetry/marionette/tests/unit/test_ping_server_received_ping.py TestPingServer.test_ping_server_received_ping | IOError: Process killed after 120s because no connection to Marionette server could be established. Check gecko.log for errors
[task 2020-04-28T04:32:20.552Z] 04:32:20 INFO - Traceback (most recent call last):
[task 2020-04-28T04:32:20.552Z] 04:32:20 INFO - File "Z:\task_1588044710\build\venv\lib\site-packages\marionette_harness\marionette_test\testcases.py", line 140, in run
[task 2020-04-28T04:32:20.552Z] 04:32:20 INFO - self.setUp()
[task 2020-04-28T04:32:20.552Z] 04:32:20 INFO - File "Z:\task_1588044710\build\tests\telemetry\marionette\tests\unit\test_ping_server_received_ping.py", line 13, in setUp
[task 2020-04-28T04:32:20.552Z] 04:32:20 INFO - super(TestPingServer, self).setUp(*args, **kwargs)
[task 2020-04-28T04:32:20.552Z] 04:32:20 INFO - File "Z:\task_1588044710\build\venv\lib\site-packages\telemetry_harness\testcase.py", line 38, in setUp
[task 2020-04-28T04:32:20.552Z] 04:32:20 INFO - super(TelemetryTestCase, self).setUp(*args, **kwargs)
[task 2020-04-28T04:32:20.552Z] 04:32:20 INFO - File "Z:\task_1588044710\build\venv\lib\site-packages\marionette_harness\runner\mixins\window_manager.py", line 16, in setUp
[task 2020-04-28T04:32:20.552Z] 04:32:20 INFO - super(WindowManagerMixin, self).setUp()
[task 2020-04-28T04:32:20.552Z] 04:32:20 INFO - File "Z:\task_1588044710\build\venv\lib\site-packages\marionette_harness\marionette_test\testcases.py", line 334, in setUp
[task 2020-04-28T04:32:20.552Z] 04:32:20 INFO - super(MarionetteTestCase, self).setUp()
[task 2020-04-28T04:32:20.553Z] 04:32:20 INFO - File "Z:\task_1588044710\build\venv\lib\site-packages\marionette_harness\marionette_test\testcases.py", line 254, in setUp
[task 2020-04-28T04:32:20.553Z] 04:32:20 INFO - self.marionette.start_session()
[task 2020-04-28T04:32:20.553Z] 04:32:20 INFO - File "Z:\task_1588044710\build\venv\lib\site-packages\marionette_driver\decorators.py", line 26, in _
[task 2020-04-28T04:32:20.553Z] 04:32:20 INFO - return func(*args, **kwargs)
[task 2020-04-28T04:32:20.553Z] 04:32:20 INFO - File "Z:\task_1588044710\build\venv\lib\site-packages\marionette_driver\marionette.py", line 1102, in start_session
[task 2020-04-28T04:32:20.553Z] 04:32:20 INFO - self.start_binary(timeout)
[task 2020-04-28T04:32:20.553Z] 04:32:20 INFO - File "Z:\task_1588044710\build\venv\lib\site-packages\marionette_driver\marionette.py", line 490, in start_binary
[task 2020-04-28T04:32:20.553Z] 04:32:20 INFO - reraise(IOError, IOError(msg.format(timeout)), sys.exc_info()[2])
[task 2020-04-28T04:32:20.553Z] 04:32:20 INFO - File "Z:\task_1588044710\build\venv\lib\site-packages\marionette_driver\marionette.py", line 482, in start_binary
[task 2020-04-28T04:32:20.553Z] 04:32:20 INFO - self.raise_for_port(timeout=timeout)
[task 2020-04-28T04:32:20.553Z] 04:32:20 INFO - File "Z:\task_1588044710\build\venv\lib\site-packages\marionette_driver\marionette.py", line 568, in raise_for_port
[task 2020-04-28T04:32:20.553Z] 04:32:20 INFO - self.host, self.port))
[task 2020-04-28T04:32:20.553Z] 04:32:20 INFO - TEST-INFO took 120200ms

Comment 1

[Intermittent Failures Robot]

1 failures in 5423 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=1633755&startday=2020-04-27&endday=2020-05-03&tree=all

Comment 2

[Intermittent Failures Robot]

1 failures in 5488 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=1633755&startday=2020-05-11&endday=2020-05-17&tree=all

Comment 3

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

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

Comment 4

[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:

• windows7-32-mingwclang: 1

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

Comment 5

[Bogdan Tara[:bogdan_tara | bogdant]]

This is still happening.

Recent failure: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=309341283&repo=mozilla-esr78&lineNumber=3307

Comment 6

[Intermittent Failures Robot]

1 failures in 5265 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=1633755&startday=2020-07-06&endday=2020-07-12&tree=all

Comment 7

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

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

Comment 8

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 1

Platform and build breakdown:

• windows10-64: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1633755&startday=2021-02-22&endday=2021-02-28&tree=all

Comment 9

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

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