Bug fixes (#642)

* additional logging when exceptions occur (#640)

* handle heartbeat keyerror correctly (#641)

* correct ext state case sensitivity check (#639)

* better old event handling (#637)

* unit test fix

* pr feedback

azurelinuxagent/common/event.py

@@ -65,8 +65,17 @@ class EventLogger(object):
         if not os.path.exists(self.event_dir):
             os.mkdir(self.event_dir)
             os.chmod(self.event_dir, 0o700)
-        if len(os.listdir(self.event_dir)) > 1000:
-            raise EventError("Too many files under: {0}".format(self.event_dir))
+
+        existing_events = os.listdir(self.event_dir)
+        if len(existing_events) >= 1000:
+            existing_events.sort()
+            oldest_files = existing_events[:-999]
+            logger.warn("Too many files under: {0}, removing oldest".format(self.event_dir))
+            try:
+                for f in oldest_files:
+                    os.remove(os.path.join(self.event_dir, f))
+            except IOError as e:
+                raise EventError(e)
 
         filename = os.path.join(self.event_dir,
                                 ustr(int(time.time() * 1000000)))

azurelinuxagent/ga/exthandlers.py

@@ -221,9 +221,9 @@ class ExtHandlersHandler(object):
 
             self.log_etag = True
 
-            state = ext_handler.properties.state
+            state = ext_handler.properties.state.lower()
             ext_handler_i.logger.info("Expected handler state: {0}", state)
-            if state == "enabled":
+            if state == u"enabled":
                 self.handle_enable(ext_handler_i)
             elif state == u"disabled":
                 self.handle_disable(ext_handler_i)
@@ -709,7 +709,7 @@ class ExtHandlerInstance(object):
             heartbeat = json.loads(heartbeat_json)[0]['heartbeat']
         except IOError as e:
             raise ExtensionError("Failed to get heartbeat file:{0}".format(e))
-        except ValueError as e:
+        except (ValueError, KeyError) as e:
             raise ExtensionError("Malformed heartbeat file: {0}".format(e))
         return heartbeat
  

azurelinuxagent/ga/update.py

@@ -27,6 +27,7 @@ import signal
 import subprocess
 import sys
 import time
+import traceback
 import zipfile
 
 import azurelinuxagent.common.conf as conf
@@ -250,6 +251,7 @@ class UpdateHandler(object):
 
         except Exception as e:
             logger.warn(u"Agent {0} failed with exception: {1}", CURRENT_AGENT, ustr(e))
+            logger.warn(traceback.format_exc())
             sys.exit(1)
             return
 

tests/common/test_event.py

@@ -0,0 +1,90 @@
+# Copyright 2017 Microsoft Corporation
+#
+# Licensed under the Apache License, Version 2.0 (the "License");
+# you may not use this file except in compliance with the License.
+# You may obtain a copy of the License at
+#
+#     http://www.apache.org/licenses/LICENSE-2.0
+#
+# Unless required by applicable law or agreed to in writing, software
+# distributed under the License is distributed on an "AS IS" BASIS,
+# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+# See the License for the specific language governing permissions and
+# limitations under the License.
+#
+# Requires Python 2.4+ and Openssl 1.0+
+#
+
+from __future__ import print_function
+
+from tests.tools import *
+from azurelinuxagent.common.event import *
+
+
+class TestEvent(AgentTestCase):
+    def test_save_event(self):
+        tmp_evt = tempfile.mkdtemp()
+        init_event_logger(tmp_evt)
+        add_event('test', message='test event')
+        self.assertTrue(len(os.listdir(tmp_evt)) == 1)
+        shutil.rmtree(tmp_evt)
+
+    def test_save_event_rollover(self):
+        tmp_evt = tempfile.mkdtemp()
+        init_event_logger(tmp_evt)
+        add_event('test', message='first event')
+        for i in range(0, 999):
+            add_event('test', message='test event {0}'.format(i))
+
+        events = os.listdir(tmp_evt)
+        events.sort()
+        self.assertTrue(len(events) == 1000)
+
+        first_event = os.path.join(tmp_evt, events[0])
+        with open(first_event) as first_fh:
+            first_event_text = first_fh.read()
+            self.assertTrue('first event' in first_event_text)
+
+        add_event('test', message='last event')
+        events = os.listdir(tmp_evt)
+        events.sort()
+        self.assertTrue(len(events) == 1000, "{0} events found, 1000 expected".format(len(events)))
+
+        first_event = os.path.join(tmp_evt, events[0])
+        with open(first_event) as first_fh:
+            first_event_text = first_fh.read()
+            self.assertFalse('first event' in first_event_text)
+            self.assertTrue('test event 0' in first_event_text)
+
+        last_event = os.path.join(tmp_evt, events[-1])
+        with open(last_event) as last_fh:
+            last_event_text = last_fh.read()
+            self.assertTrue('last event' in last_event_text)
+
+        shutil.rmtree(tmp_evt)
+
+    def test_save_event_cleanup(self):
+        tmp_evt = tempfile.mkdtemp()
+        init_event_logger(tmp_evt)
+
+        for i in range(0, 2000):
+            evt = os.path.join(tmp_evt, '{0}.tld'.format(ustr(1491004920536531 + i)))
+            with open(evt, 'w') as fh:
+                fh.write('test event {0}'.format(i))
+
+        events = os.listdir(tmp_evt)
+        self.assertTrue(len(events) == 2000, "{0} events found, 2000 expected".format(len(events)))
+        add_event('test', message='last event')
+
+        events = os.listdir(tmp_evt)
+        events.sort()
+        self.assertTrue(len(events) == 1000, "{0} events found, 1000 expected".format(len(events)))
+        first_event = os.path.join(tmp_evt, events[0])
+        with open(first_event) as first_fh:
+            first_event_text = first_fh.read()
+            self.assertTrue('test event 1001' in first_event_text)
+
+        last_event = os.path.join(tmp_evt, events[-1])
+        with open(last_event) as last_fh:
+            last_event_text = last_fh.read()
+            self.assertTrue('last event' in last_event_text)

tests/ga/test_update.py

@@ -1083,7 +1083,6 @@ class TestUpdate(UpdateTestCase):
         self._test_run_latest(mock_child=mock_child, mock_time=mock_time)
         self.assertEqual(1, mock_child.poll.call_count)
         self.assertEqual(0, mock_child.wait.call_count)
-        self.assertEqual(2, mock_time.time_call_count)
         return
 
     def test_run_latest_defaults_to_current(self):