Merge pull request #813 from brendandixon/master

[#801] -- Agent fails to clean-up PID files

README.md

@@ -168,7 +168,10 @@ script.
 ### CONFIGURATION
 
 A configuration file (/etc/waagent.conf) controls the actions of
-waagent. A sample configuration file is shown below:
+waagent. Blank lines and lines whose first character is a `#` are
+ignored (end-of-line comments are *not* supported).
+
+A sample configuration file is shown below:
 
 ```
 Provisioning.Enabled=y

azurelinuxagent/agent.py

@@ -64,7 +64,19 @@ class Agent(object):
         logger.add_logger_appender(logger.AppenderType.CONSOLE, level,
                                  path="/dev/console")
 
+        ext_log_dir = conf.get_ext_log_dir()
+        try:
+            if os.path.isfile(ext_log_dir):
+                raise Exception("{0} is a file".format(ext_log_dir))
+            if not os.path.isdir(ext_log_dir):
+                os.makedirs(ext_log_dir)
+        except Exception as e:
+            logger.error(
+                "Exception occurred while creating extension "
+                "log directory {0}: {1}".format(ext_log_dir, e))
+
         #Init event reporter
+        event.init_event_status(conf.get_lib_dir())
         event_dir = os.path.join(conf.get_lib_dir(), "events")
         event.init_event_logger(event_dir)
         event.enable_unhandled_err_dump("WALA")

azurelinuxagent/common/event.py

@@ -67,25 +67,29 @@ class EventStatus(object):
     EVENT_STATUS_FILE = "event_status.json"
 
     def __init__(self, status_dir=conf.get_lib_dir()):
-        self._path = os.path.join(status_dir, EventStatus.EVENT_STATUS_FILE)
-        self._load()
+        self._path = None
+        self._status = {}
 
     def clear(self):
-        self.status = {}
+        self._status = {}
         self._save()
 
     def event_marked(self, name, version, op):
-        return self._event_name(name, version, op) in self.status
+        return self._event_name(name, version, op) in self._status
 
     def event_succeeded(self, name, version, op):
         event = self._event_name(name, version, op)
-        if event not in self.status:
+        if event not in self._status:
             return True
-        return self.status[event] == True
+        return self._status[event] == True
+
+    def initialize(self, status_dir=conf.get_lib_dir()):
+        self._path = os.path.join(status_dir, EventStatus.EVENT_STATUS_FILE)
+        self._load()
 
     def mark_event_status(self, name, version, op, status):
         event = self._event_name(name, version, op)
-        self.status[event] = (status == True)
+        self._status[event] = (status == True)
         self._save()
 
     def _event_name(self, name, version, op):
@@ -93,18 +97,18 @@ class EventStatus(object):
 
     def _load(self):
         try:
-            self.status = {}
+            self._status = {}
             if os.path.isfile(self._path):
                 with open(self._path, 'r') as f:
-                    self.status = json.load(f)
+                    self._status = json.load(f)
         except Exception as e:
             logger.warn("Exception occurred loading event status: {0}".format(e))
-            self.status = {}
+            self._status = {}
 
     def _save(self):
         try:
             with open(self._path, 'w') as f:
-                json.dump(self.status, f)
+                json.dump(self._status, f)
         except Exception as e:
             logger.warn("Exception occurred saving event status: {0}".format(e))
 
@@ -130,7 +134,7 @@ class EventLogger(object):
 
     def save_event(self, data):
         if self.event_dir is None:
-            logger.warn("Event reporter is not initialized.")
+            logger.warn("Cannot save event -- Event reporter is not initialized.")
             return
 
         if not os.path.exists(self.event_dir):
@@ -230,7 +234,7 @@ def add_event(name, op="", is_success=True, duration=0, version=CURRENT_VERSION,
               message="", evt_type="", is_internal=False, log_event=True,
               reporter=__event_logger__):
     if reporter.event_dir is None:
-        logger.warn("Event reporter is not initialized.")
+        logger.warn("Cannot add event -- Event reporter is not initialized.")
         _log_event(name, op, message, is_success=is_success)
         return
 
@@ -246,7 +250,7 @@ def add_periodic(
     message="", evt_type="", is_internal=False, log_event=True, force=False,
     reporter=__event_logger__):
     if reporter.event_dir is None:
-        logger.warn("Event reporter is not initialized.")
+        logger.warn("Cannot add periodic event -- Event reporter is not initialized.")
         _log_event(name, op, message, is_success=is_success)
         return
 
@@ -266,9 +270,11 @@ def should_emit_event(name, version, op, status):
         not __event_status__.event_marked(name, version, op) or \
         __event_status__.event_succeeded(name, version, op) != status
 
-def init_event_logger(event_dir, reporter=__event_logger__):
-    reporter.event_dir = event_dir
+def init_event_logger(event_dir):
+    __event_logger__.event_dir = event_dir
 
+def init_event_status(status_dir):
+    __event_status__.initialize(status_dir)
 
 def dump_unhandled_err(name):
     if hasattr(sys, 'last_type') and hasattr(sys, 'last_value') and \

azurelinuxagent/ga/monitor.py

@@ -36,8 +36,8 @@ from azurelinuxagent.common.protocol.restapi import TelemetryEventParam, \
                                                     set_properties
 from azurelinuxagent.common.utils.textutil import parse_doc, findall, find, getattrib
 from azurelinuxagent.common.version import DISTRO_NAME, DISTRO_VERSION, \
-                                            DISTRO_CODE_NAME, AGENT_LONG_VERSION, \
-                                            AGENT_NAME, CURRENT_VERSION
+            DISTRO_CODE_NAME, AGENT_LONG_VERSION, \
+            AGENT_NAME, CURRENT_AGENT, CURRENT_VERSION
 
 
 def parse_event(data_str):

azurelinuxagent/ga/update.py

@@ -426,11 +426,12 @@ class UpdateHandler(object):
         return len(self.agents) > 0 and self.agents[0].version > base_version
 
     def _ensure_no_orphans(self, orphan_wait_interval=ORPHAN_WAIT_INTERVAL):
-        previous_pid_file, pid_file = self._write_pid_file()
-        if previous_pid_file is not None:
+        pid_files, ignored = self._write_pid_file()
+        for pid_file in pid_files:
             try:
-                pid = fileutil.read_file(previous_pid_file)
+                pid = fileutil.read_file(pid_file)
                 wait_interval = orphan_wait_interval
+
                 while self.osutil.check_pid_alive(pid):
                     wait_interval -= GOAL_STATE_INTERVAL
                     if wait_interval <= 0:
@@ -447,6 +448,8 @@ class UpdateHandler(object):
                         pid)
                     time.sleep(GOAL_STATE_INTERVAL)
 
+                os.remove(pid_file)
+
             except Exception as e:
                 logger.warn(
                     u"Exception occurred waiting for orphan agent to terminate: {0}",
@@ -503,22 +506,18 @@ class UpdateHandler(object):
                                     protocol.client \
                                 else None
 
-    def _get_pid_files(self):
+    def _get_pid_parts(self):
         pid_file = conf.get_agent_pid_file_path()
-        
         pid_dir = os.path.dirname(pid_file)
         pid_name = os.path.basename(pid_file)
-        
         pid_re = re.compile("(\d+)_{0}".format(re.escape(pid_name)))
-        pid_files = [int(pid_re.match(f).group(1)) for f in os.listdir(pid_dir) if pid_re.match(f)]
-        pid_files.sort()
+        return pid_dir, pid_name, pid_re
 
-        pid_index = -1 if len(pid_files) <= 0 else pid_files[-1]
-        previous_pid_file = None \
-                        if pid_index < 0 \
-                        else os.path.join(pid_dir, "{0}_{1}".format(pid_index, pid_name))
-        pid_file = os.path.join(pid_dir, "{0}_{1}".format(pid_index+1, pid_name))
-        return previous_pid_file, pid_file
+    def _get_pid_files(self):
+        pid_dir, pid_name, pid_re = self._get_pid_parts()
+        pid_files = [os.path.join(pid_dir, f) for f in os.listdir(pid_dir) if pid_re.match(f)]
+        pid_files.sort(key=lambda f: int(pid_re.match(os.path.basename(f)).group(1)))
+        return pid_files
 
     @property
     def _is_clean_start(self):
@@ -615,7 +614,18 @@ class UpdateHandler(object):
         return
 
     def _write_pid_file(self):
-        previous_pid_file, pid_file = self._get_pid_files()
+        pid_files = self._get_pid_files()
+
+        pid_dir, pid_name, pid_re = self._get_pid_parts()
+
+        previous_pid_file = None \
+                        if len(pid_files) <= 0 \
+                        else pid_files[-1]
+        pid_index = -1 \
+                    if previous_pid_file is None \
+                    else int(pid_re.match(os.path.basename(previous_pid_file)).group(1))
+        pid_file = os.path.join(pid_dir, "{0}_{1}".format(pid_index+1, pid_name))
+
         try:
             fileutil.write_file(pid_file, ustr(os.getpid()))
             logger.info(u"{0} running as process {1}", CURRENT_AGENT, ustr(os.getpid()))
@@ -626,7 +636,8 @@ class UpdateHandler(object):
                 CURRENT_AGENT,
                 pid_file,
                 ustr(e))
-        return previous_pid_file, pid_file
+
+        return pid_files, pid_file
 
 
 class GuestAgent(object):

tests/common/test_event.py

@@ -22,7 +22,7 @@ from datetime import datetime
 import azurelinuxagent.common.event as event
 import azurelinuxagent.common.logger as logger
 
-from azurelinuxagent.common.event import init_event_logger, add_event, \
+from azurelinuxagent.common.event import add_event, \
                                     mark_event_status, should_emit_event
 from azurelinuxagent.common.future import ustr
 from azurelinuxagent.common.version import CURRENT_VERSION
@@ -32,18 +32,19 @@ from tests.tools import *
 
 class TestEvent(AgentTestCase):
     def test_event_status_event_marked(self):
-        d = tempfile.mkdtemp()
-        es = event.EventStatus(d)
+        es = event.__event_status__
 
         self.assertFalse(es.event_marked("Foo", "1.2", "FauxOperation"))
         es.mark_event_status("Foo", "1.2", "FauxOperation", True)
         self.assertTrue(es.event_marked("Foo", "1.2", "FauxOperation"))
 
-        es = event.EventStatus(d)
+        event.__event_status__ = event.EventStatus()
+        event.init_event_status(self.tmp_dir)
+        es = event.__event_status__
         self.assertTrue(es.event_marked("Foo", "1.2", "FauxOperation"))
 
     def test_event_status_defaults_to_success(self):
-        es = event.EventStatus(tempfile.mkdtemp())
+        es = event.__event_status__
         self.assertTrue(es.event_succeeded("Foo", "1.2", "FauxOperation"))
 
     def test_event_status_records_status(self):
@@ -57,13 +58,14 @@ class TestEvent(AgentTestCase):
         self.assertFalse(es.event_succeeded("Foo", "1.2", "FauxOperation"))
 
     def test_event_status_preserves_state(self):
-        d = tempfile.mkdtemp()
-        es = event.EventStatus(d)
+        es = event.__event_status__
 
         es.mark_event_status("Foo", "1.2", "FauxOperation", False)
         self.assertFalse(es.event_succeeded("Foo", "1.2", "FauxOperation"))
 
-        es = event.EventStatus(d)
+        event.__event_status__ = event.EventStatus()
+        event.init_event_status(self.tmp_dir)
+        es = event.__event_status__
         self.assertFalse(es.event_succeeded("Foo", "1.2", "FauxOperation"))
 
     def test_should_emit_event_ignores_unknown_operations(self):
@@ -107,7 +109,6 @@ class TestEvent(AgentTestCase):
 
     @patch('azurelinuxagent.common.event.EventLogger.add_event')
     def test_periodic_emits_if_not_previously_sent(self, mock_event):
-        init_event_logger(tempfile.mkdtemp())
         event.__event_logger__.reset_periodic()
 
         event.add_periodic(logger.EVERY_DAY, "FauxEvent")
@@ -115,7 +116,6 @@ class TestEvent(AgentTestCase):
 
     @patch('azurelinuxagent.common.event.EventLogger.add_event')
     def test_periodic_does_not_emit_if_previously_sent(self, mock_event):
-        init_event_logger(tempfile.mkdtemp())
         event.__event_logger__.reset_periodic()
 
         event.add_periodic(logger.EVERY_DAY, "FauxEvent")
@@ -126,7 +126,6 @@ class TestEvent(AgentTestCase):
 
     @patch('azurelinuxagent.common.event.EventLogger.add_event')
     def test_periodic_emits_if_forced(self, mock_event):
-        init_event_logger(tempfile.mkdtemp())
         event.__event_logger__.reset_periodic()
 
         event.add_periodic(logger.EVERY_DAY, "FauxEvent")
@@ -137,7 +136,6 @@ class TestEvent(AgentTestCase):
 
     @patch('azurelinuxagent.common.event.EventLogger.add_event')
     def test_periodic_emits_after_elapsed_delta(self, mock_event):
-        init_event_logger(tempfile.mkdtemp())
         event.__event_logger__.reset_periodic()
 
         event.add_periodic(logger.EVERY_DAY, "FauxEvent")
@@ -154,7 +152,6 @@ class TestEvent(AgentTestCase):
 
     @patch('azurelinuxagent.common.event.EventLogger.add_event')
     def test_periodic_forwards_args(self, mock_event):
-        init_event_logger(tempfile.mkdtemp())
         event.__event_logger__.reset_periodic()
 
         event.add_periodic(logger.EVERY_DAY, "FauxEvent")
@@ -164,68 +161,58 @@ class TestEvent(AgentTestCase):
             log_event=True, message='', op='', version=str(CURRENT_VERSION))
 
     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)
+        self.assertTrue(len(os.listdir(self.tmp_dir)) == 1)
 
     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 = os.listdir(self.tmp_dir)
         events.sort()
         self.assertTrue(len(events) == 1000)
 
-        first_event = os.path.join(tmp_evt, events[0])
+        first_event = os.path.join(self.tmp_dir, 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 = os.listdir(self.tmp_dir)
         events.sort()
         self.assertTrue(len(events) == 1000, "{0} events found, 1000 expected".format(len(events)))
 
-        first_event = os.path.join(tmp_evt, events[0])
+        first_event = os.path.join(self.tmp_dir, 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])
+        last_event = os.path.join(self.tmp_dir, 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)))
+            evt = os.path.join(self.tmp_dir, '{0}.tld'.format(ustr(1491004920536531 + i)))
             with open(evt, 'w') as fh:
                 fh.write('test event {0}'.format(i))
 
-        events = os.listdir(tmp_evt)
+        events = os.listdir(self.tmp_dir)
         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 = os.listdir(self.tmp_dir)
         events.sort()
         self.assertTrue(len(events) == 1000, "{0} events found, 1000 expected".format(len(events)))
-        first_event = os.path.join(tmp_evt, events[0])
+        first_event = os.path.join(self.tmp_dir, 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])
+        last_event = os.path.join(self.tmp_dir, 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

@@ -22,6 +22,7 @@ from datetime import datetime
 import json
 import shutil
 
+from azurelinuxagent.common.event import *
 from azurelinuxagent.common.protocol.hostplugin import *
 from azurelinuxagent.common.protocol.metadata import *
 from azurelinuxagent.common.protocol.wire import *
@@ -912,7 +913,7 @@ class TestUpdate(UpdateTestCase):
             v = a.version
         return
 
-    def _test_ensure_no_orphans(self, invocations=3, interval=ORPHAN_WAIT_INTERVAL):
+    def _test_ensure_no_orphans(self, invocations=3, interval=ORPHAN_WAIT_INTERVAL, pid_count=0):
         with patch.object(self.update_handler, 'osutil') as mock_util:
             # Note:
             # - Python only allows mutations of objects to which a function has
@@ -927,15 +928,20 @@ class TestUpdate(UpdateTestCase):
 
             mock_util.check_pid_alive = Mock(side_effect=iterator)
 
+            pid_files = self.update_handler._get_pid_files()
+            self.assertEqual(pid_count, len(pid_files))
+
             with patch('os.getpid', return_value=42):
                 with patch('time.sleep', return_value=None) as mock_sleep:
                     self.update_handler._ensure_no_orphans(orphan_wait_interval=interval)
+                    for pid_file in pid_files:
+                        self.assertFalse(os.path.exists(pid_file))
                     return mock_util.check_pid_alive.call_count, mock_sleep.call_count
         return
 
     def test_ensure_no_orphans(self):
         fileutil.write_file(os.path.join(self.tmp_dir, "0_waagent.pid"), ustr(41))
-        calls, sleeps = self._test_ensure_no_orphans(invocations=3)
+        calls, sleeps = self._test_ensure_no_orphans(invocations=3, pid_count=1)
         self.assertEqual(3, calls)
         self.assertEqual(2, sleeps)
         return
@@ -958,7 +964,8 @@ class TestUpdate(UpdateTestCase):
         with patch('os.kill') as mock_kill:
             calls, sleeps = self._test_ensure_no_orphans(
                                         invocations=4,
-                                        interval=3*GOAL_STATE_INTERVAL)
+                                        interval=3*GOAL_STATE_INTERVAL,
+                                        pid_count=1)
             self.assertEqual(3, calls)
             self.assertEqual(2, sleeps)
             self.assertEqual(1, mock_kill.call_count)
@@ -1069,17 +1076,19 @@ class TestUpdate(UpdateTestCase):
         return
 
     def test_get_pid_files(self):
-        previous_pid_file, pid_file, = self.update_handler._get_pid_files()
-        self.assertEqual(None, previous_pid_file)
-        self.assertEqual("0_waagent.pid", os.path.basename(pid_file))
+        pid_files = self.update_handler._get_pid_files()
+        self.assertEqual(0, len(pid_files))
         return
 
     def test_get_pid_files_returns_previous(self):
         for n in range(1250):
             fileutil.write_file(os.path.join(self.tmp_dir, str(n)+"_waagent.pid"), ustr(n+1))
-        previous_pid_file, pid_file, = self.update_handler._get_pid_files()
-        self.assertEqual("1249_waagent.pid", os.path.basename(previous_pid_file))
-        self.assertEqual("1250_waagent.pid", os.path.basename(pid_file))
+        pid_files = self.update_handler._get_pid_files()
+        self.assertEqual(1250, len(pid_files))
+
+        pid_dir, pid_name, pid_re = self.update_handler._get_pid_parts()
+        for p in pid_files:
+            self.assertTrue(pid_re.match(os.path.basename(p)))
         return
 
     def test_is_clean_start_returns_true_when_no_sentinal(self):
@@ -1499,8 +1508,9 @@ class TestUpdate(UpdateTestCase):
         for n in range(1112):
             fileutil.write_file(os.path.join(self.tmp_dir, str(n)+"_waagent.pid"), ustr(n+1))
         with patch('os.getpid', return_value=1112):
-            previous_pid_file, pid_file = self.update_handler._write_pid_file()
-            self.assertEqual("1111_waagent.pid", os.path.basename(previous_pid_file))
+            pid_files, pid_file = self.update_handler._write_pid_file()
+            self.assertEqual(1112, len(pid_files))
+            self.assertEqual("1111_waagent.pid", os.path.basename(pid_files[-1]))
             self.assertEqual("1112_waagent.pid", os.path.basename(pid_file))
             self.assertEqual(fileutil.read_file(pid_file), ustr(1112))
         return
@@ -1508,8 +1518,8 @@ class TestUpdate(UpdateTestCase):
     def test_write_pid_file_ignores_exceptions(self):
         with patch('azurelinuxagent.common.utils.fileutil.write_file', side_effect=Exception):
             with patch('os.getpid', return_value=42):
-                previous_pid_file, pid_file = self.update_handler._write_pid_file()
-                self.assertEqual(None, previous_pid_file)
+                pid_files, pid_file = self.update_handler._write_pid_file()
+                self.assertEqual(0, len(pid_files))
                 self.assertEqual(None, pid_file)
         return
 

tests/test_agent.py

@@ -90,3 +90,28 @@ class TestAgent(AgentTestCase):
 
         mock_daemon.run.assert_called_once_with(child_args="-configuration-path:/foo/bar.conf")
         mock_load.assert_called_once()
+
+    @patch("azurelinuxagent.common.conf.get_ext_log_dir")
+    def test_agent_ensures_extension_log_directory(self, mock_dir):
+        ext_log_dir = os.path.join(self.tmp_dir, "FauxLogDir")
+        mock_dir.return_value = ext_log_dir
+
+        self.assertFalse(os.path.isdir(ext_log_dir))
+        agent = Agent(False,
+                    conf_file_path=os.path.join(data_dir, "test_waagent.conf"))
+        self.assertTrue(os.path.isdir(ext_log_dir))
+
+    @patch("azurelinuxagent.common.logger.error")
+    @patch("azurelinuxagent.common.conf.get_ext_log_dir")
+    def test_agent_logs_if_extension_log_directory_is_a_file(self, mock_dir, mock_log):
+        ext_log_dir = os.path.join(self.tmp_dir, "FauxLogDir")
+        mock_dir.return_value = ext_log_dir
+        fileutil.write_file(ext_log_dir, "Foo")
+
+        self.assertTrue(os.path.isfile(ext_log_dir))
+        self.assertFalse(os.path.isdir(ext_log_dir))
+        agent = Agent(False,
+                    conf_file_path=os.path.join(data_dir, "test_waagent.conf"))
+        self.assertTrue(os.path.isfile(ext_log_dir))
+        self.assertFalse(os.path.isdir(ext_log_dir))
+        mock_log.assert_called_once()

tests/tools.py

@@ -26,8 +26,10 @@ import tempfile
 import unittest
 from functools import wraps
 
+import azurelinuxagent.common.event as event
 import azurelinuxagent.common.conf as conf
 import azurelinuxagent.common.logger as logger
+
 from azurelinuxagent.common.version import PY_VERSION_MAJOR
 
 #Import mock module for Python2 and Python3
@@ -51,14 +53,21 @@ if debug:
 class AgentTestCase(unittest.TestCase):
     def setUp(self):
         prefix = "{0}_".format(self.__class__.__name__)
+
         self.tmp_dir = tempfile.mkdtemp(prefix=prefix)
         self.test_file = 'test_file'
+
         conf.get_autoupdate_enabled = Mock(return_value=True)
         conf.get_lib_dir = Mock(return_value=self.tmp_dir)
+
         ext_log_dir = os.path.join(self.tmp_dir, "azure")
         conf.get_ext_log_dir = Mock(return_value=ext_log_dir)
+
         conf.get_agent_pid_file_path = Mock(return_value=os.path.join(self.tmp_dir, "waagent.pid"))
 
+        event.init_event_status(self.tmp_dir)
+        event.init_event_logger(self.tmp_dir)
+
     def tearDown(self):
         if not debug and self.tmp_dir is not None:
             shutil.rmtree(self.tmp_dir)