Repository: Azure/WALinuxAgent (python)

Issue:
Download operation failure
```Exception retrieving agent manifests: [ProtocolError] /var/lib/waagent/GoalState.1.xml is missing.```


Pull request description:
more debug for download failures
Closes #945

Patch:
diff --git a/azurelinuxagent/common/errorstate.py b/azurelinuxagent/common/errorstate.py
new file mode 100644
index 00000000..750aa77b
--- /dev/null
+++ b/azurelinuxagent/common/errorstate.py
@@ -0,0 +1,31 @@
+from datetime import datetime, timedelta
+
+ERROR_STATE_DELTA = timedelta(minutes=15)
+
+
+class ErrorState(object):
+    def __init__(self, min_timedelta = ERROR_STATE_DELTA):
+        self.min_timedelta = min_timedelta
+
+        self.count = 0
+        self.timestamp = None
+
+    def incr(self):
+        if self.count == 0:
+            self.timestamp = datetime.utcnow()
+
+        self.count += 1
+
+    def reset(self):
+        self.count = 0
+        self.timestamp = None
+
+    def is_triggered(self):
+        if self.timestamp is None:
+            return False
+
+        delta = datetime.utcnow() - self.timestamp
+        if delta >= self.min_timedelta:
+            return True
+
+        return False
diff --git a/azurelinuxagent/ga/exthandlers.py b/azurelinuxagent/ga/exthandlers.py
index df5db7e5..51ed5d36 100644
--- a/azurelinuxagent/ga/exthandlers.py
+++ b/azurelinuxagent/ga/exthandlers.py
@@ -35,6 +35,7 @@ import azurelinuxagent.common.utils.fileutil as fileutil
 import azurelinuxagent.common.utils.restutil as restutil
 import azurelinuxagent.common.utils.shellutil as shellutil
 import azurelinuxagent.common.version as version
+from azurelinuxagent.common.errorstate import ErrorState, ERROR_STATE_DELTA
 
 from azurelinuxagent.common.event import add_event, WALAEventOperation, elapsed_milliseconds
 from azurelinuxagent.common.exception import ExtensionError, ProtocolError, HttpError
@@ -181,6 +182,8 @@ class ExtHandlersHandler(object):
         self.log_report = False
         self.log_etag = True
 
+        self.report_status_error_state = ErrorState()
+
     def run(self):
         self.ext_handlers, etag = None, None
         try:
@@ -418,7 +421,7 @@ class ExtHandlersHandler(object):
                 ext_handler_i.disable()
             ext_handler_i.uninstall()
         ext_handler_i.rm_ext_handler_dir()
-    
+
     def report_ext_handlers_status(self):
         """Go through handler_state dir, collect and report status"""
         vm_status = VMStatus(status="Ready", message="Guest Agent is running")
@@ -439,7 +442,9 @@ class ExtHandlersHandler(object):
             self.protocol.report_vm_status(vm_status)
             if self.log_report:
                 logger.verbose("Completed vm agent status report")
+            self.report_status_error_state.reset()
         except ProtocolError as e:
+            self.report_status_error_state.incr()
             message = "Failed to report vm agent status: {0}".format(e)
             add_event(AGENT_NAME,
                 version=CURRENT_VERSION,
@@ -447,6 +452,18 @@ class ExtHandlersHandler(object):
                 is_success=False,
                 message=message)
 
+        if self.report_status_error_state.is_triggered():
+            message = "Failed to report vm agent status for more than {0}"\
+                .format(ERROR_STATE_DELTA)
+
+            add_event(AGENT_NAME,
+                version=CURRENT_VERSION,
+                op=WALAEventOperation.ExtensionProcessing,
+                is_success=False,
+                message=message)
+
+            self.report_status_error_state.reset()
+
     def report_ext_handler_status(self, vm_status, ext_handler):
         ext_handler_i = ExtHandlerInstance(ext_handler, self.protocol)
         
diff --git a/azurelinuxagent/ga/update.py b/azurelinuxagent/ga/update.py
index 03d94c39..26009299 100644
--- a/azurelinuxagent/ga/update.py
+++ b/azurelinuxagent/ga/update.py
@@ -660,7 +660,7 @@ class UpdateHandler(object):
                     continue
 
                 msg = u"Exception retrieving agent manifests: {0}".format(
-                            ustr(e))
+                            ustr(traceback.format_exc()))
                 logger.warn(msg)
                 add_event(
                     AGENT_NAME,


Test patch:
diff --git a/tests/common/test_errorstate.py b/tests/common/test_errorstate.py
new file mode 100644
index 00000000..7513fe59
--- /dev/null
+++ b/tests/common/test_errorstate.py
@@ -0,0 +1,69 @@
+from datetime import timedelta
+
+from azurelinuxagent.common.errorstate import *
+from tests.tools import *
+
+
+class TestErrorState(unittest.TestCase):
+    def test_errorstate00(self):
+        """
+        If ErrorState is never incremented, it will never trigger.
+        """
+        test_subject = ErrorState(timedelta(seconds=10000))
+        self.assertFalse(test_subject.is_triggered())
+        self.assertEqual(0, test_subject.count)
+
+    def test_errorstate01(self):
+        """
+        If ErrorState is never incremented, and the timedelta is zero it will
+        not trigger.
+        """
+        test_subject = ErrorState(timedelta(seconds=0))
+        self.assertFalse(test_subject.is_triggered())
+        self.assertEqual(0, test_subject.count)
+
+    def test_errorstate02(self):
+        """
+        If ErrorState is triggered, and the current time is within timedelta
+        of now it will trigger.
+        """
+        test_subject = ErrorState(timedelta(seconds=0))
+        test_subject.incr()
+
+
+        self.assertTrue(test_subject.is_triggered())
+        self.assertEqual(1, test_subject.count)
+
+    @patch('azurelinuxagent.common.errorstate.datetime')
+    def test_errorstate03(self, mock_time):
+        """
+        ErrorState will not trigger until
+         1. ErrorState has been incr() at least once.
+         2. The timedelta from the first incr() has elapsed.
+        """
+        test_subject = ErrorState(timedelta(minutes=15))
+
+        for x in range(1, 10):
+            mock_time.utcnow = Mock(return_value=datetime.utcnow() + timedelta(minutes=x))
+
+            test_subject.incr()
+            self.assertFalse(test_subject.is_triggered())
+
+        mock_time.utcnow = Mock(return_value=datetime.utcnow() + timedelta(minutes=30))
+        test_subject.incr()
+        self.assertTrue(test_subject.is_triggered())
+
+    def test_errorstate04(self):
+        """
+        If ErrorState is reset the timestamp of the last incr() is reset to
+        None.
+        """
+
+        test_subject = ErrorState(timedelta(minutes=15))
+        self.assertTrue(test_subject.timestamp is None)
+
+        test_subject.incr()
+        self.assertTrue(test_subject.timestamp is not None)
+
+        test_subject.reset()
+        self.assertTrue(test_subject.timestamp is None)