Fix flaky ExtensionCleanupTest class

[larohra]

Description

Increase sleep timeout for flaky test and added more debugging msg

Issue #

---

PR information

• The title of the PR is clear and informative.
• There are a small number of commits, each of which has an informative message. This means that previously merged commits do not appear in the history of the PR. For information on cleaning up the commits in your pull request, see this page.
• Except for special cases involving multiple contributors, the PR is started from a fork of the main repository, not a branch.
• If applicable, the PR references the bug/issue that it fixes in the description.
• New Unit tests were added for the changes made and Travis.CI is passing.

Quality of Code and Contribution Guidelines

• I have read the contribution guidelines.

[codecov]

Codecov Report

Merging #1898 into develop will not change coverage.
The diff coverage is n/a.

@@           Coverage Diff            @@
##           develop    #1898   +/-   ##
========================================
  Coverage    69.59%   69.59%           
========================================
  Files           84       84           
  Lines        11704    11704           
  Branches      1627     1627           
========================================
  Hits          8145     8145           
  Misses        3213     3213           
  Partials       346      346           

---

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update e48c207...cfc0fb3. Read the comment docs.

[narrieta]

shouldn't you force a test failure here?

self.fail("...message...")

[larohra]

I'm re-raising the Exception below. It would be the same thing. The only reason I added a try catch is to print the handler_Statuses incase we need the debugging info later. That is how I was able to initially figure out that Timeout was causing the race condition.

[narrieta]

The test will Error rather than Fail. Maybe I'm misunderstanding your test. Who would raise?

[larohra]

In case of assertion failures, an AssertionError (or something similar) is raised. In that case I'm just printing the info and moving on with the execution. It should technically fail the test as if nothing happened.

Random example:

All ExtensionHandlers: [{u'status': u'Ready', u'code': 0, u'formattedMessage': {u'lang': u'en-US', u'message': u'Plugin enabled'}, u'runtimeSettingsStatus': {u'settingsStatus': {u'status': {u'status': u'success', u'code': 0, u'name': u'OSTCExtensions.ExampleHandlerLinux', u'formattedMessage': {u'lang': u'en-US', u'message': None}, u'configurationAppliedTime': None, u'operation': None}, u'version': 1.0, u'timestampUTC': u'2020-05-29T19:52:49Z'}, u'sequenceNumber': 0}, u'useExactVersion': True, u'handlerVersion': u'1.0.0', u'handlerName': u'OSTCExtensions.ExampleHandlerLinux'}, {u'status': u'Ready', u'code': 0, u'formattedMessage': {u'lang': u'en-US', u'message': u'Plugin enabled'}, u'runtimeSettingsStatus': {u'settingsStatus': {u'status': {u'status': u'success', u'code': 0, u'name': u'Microsoft.Powershell.ExampleExtension', u'formattedMessage': {u'lang': u'en-US', u'message': None}, u'configurationAppliedTime': None, u'operation': None}, u'version': 1.0, u'timestampUTC': u'2020-05-29T19:52:49Z'}, u'sequenceNumber': 0}, u'useExactVersion': True, u'handlerVersion': u'1.0.0', u'handlerName': u'Microsoft.Powershell.ExampleExtension'}, {u'status': u'Ready', u'code': 0, u'formattedMessage': {u'lang': u'en-US', u'message': u'Plugin enabled'}, u'runtimeSettingsStatus': {u'settingsStatus': {u'status': {u'status': u'success', u'code': 0, u'name': u'Microsoft.EnterpriseCloud.Monitoring.ExampleHandlerLinux', u'formattedMessage': {u'lang': u'en-US', u'message': None}, u'configurationAppliedTime': None, u'operation': None}, u'version': 1.0, u'timestampUTC': u'2020-05-29T19:52:49Z'}, u'sequenceNumber': 0}, u'useExactVersion': True, u'handlerVersion': u'1.0.0', u'handlerName': u'Microsoft.EnterpriseCloud.Monitoring.ExampleHandlerLinux'}, {u'status': u'Ready', u'code': 0, u'formattedMessage': {u'lang': u'en-US', u'message': u'Plugin enabled'}, u'runtimeSettingsStatus': {u'settingsStatus': {u'status': {u'status': u'success', u'code': 0, u'name': u'Microsoft.CPlat.Core.ExampleExtensionLinux', u'formattedMessage': {u'lang': u'en-US', u'message': None}, u'configurationAppliedTime': None, u'operation': None}, u'version': 1.0, u'timestampUTC': u'2020-05-29T19:52:49Z'}, u'sequenceNumber': 0}, u'useExactVersion': True, u'handlerVersion': u'1.0.0', u'handlerName': u'Microsoft.CPlat.Core.ExampleExtensionLinux'}, {u'status': u'Ready', u'code': 0, u'formattedMessage': {u'lang': u'en-US', u'message': u'Plugin enabled'}, u'runtimeSettingsStatus': {u'settingsStatus': {u'status': {u'status': u'success', u'code': 0, u'name': u'Microsoft.OSTCExtensions.Edp.ExampleExtensionLinuxInTest', u'formattedMessage': {u'lang': u'en-US', u'message': None}, u'configurationAppliedTime': None, u'operation': None}, u'version': 1.0, u'timestampUTC': u'2020-05-29T19:52:49Z'}, u'sequenceNumber': 0}, u'useExactVersion': True, u'handlerVersion': u'1.0.0', u'handlerName': u'Microsoft.OSTCExtensions.Edp.ExampleExtensionLinuxInTest'}]


5 != 100000

Expected :100000
Actual   :5
<Click to see difference>

Traceback (most recent call last):
  File "/usr/lib/python2.7/unittest/case.py", line 329, in run
    testMethod()
  File "/home/larohra/WALinuxAgent-larohra-fork/tests/ga/test_extension.py", line 147, in test_cleanup_leaves_installed_extensions
    version="1.0.0")
  File "/home/larohra/WALinuxAgent-larohra-fork/tests/ga/test_extension.py", line 114, in _assert_ext_handler_status
    self.assertEqual(100000, len(handler_statuses))

[narrieta]

You should add the debug info as part of the assert message:

debug_info = "All ExtensionHandlers: {0}".format(handler_statuses)
...
self.assertEqual(expected_ext_handler_count, len(handler_statuses), "The number of handlers is incorrect.\n{0}'.format(debug_info))
...
etc

[larohra]

Ahh good point! (Duh moment for me lol). Updated! :)