Repository: Azure/WALinuxAgent (python)

Issue:
Keep track of put status state
We should emit telemetry if a vm cannot report status successfully with a certain timeframe, this will help with alerting and health monitoring. Perhaps 15 minutes?

Suggest we add a timestamp in memory to `wire.py` and update/report it in or around this method: https://github.com/Azure/WALinuxAgent/blob/ab261b5f2ed0dfce4dd94adf924e68e0aaff5e7b/azurelinuxagent/common/protocol/wire.py#L189 

Pull request description:
Report prolonged report status failures
The agent report transient failures, but this is not very indicative of
customer failures.  The transient failures generally resolve themselves, so the
transients are not very useful for a dashboard.  This change tracks failures
that repeat for 15 minutes, and then report them.  If an operation fails and
succeeds within 15 minutes, the timer resets.  It must be a continual stream of
errors for 15 minutes for this telemetry event to trigger.

Closes #956 

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)
         


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)