[1chb1n,r=james-page] Resync helpers and update amulet tests to avoid config-changed restart races.

Makefile

@@ -9,7 +9,7 @@ lint:
 test:
 	@# Bundletester expects unit tests here.
 	@echo Starting unit tests...
-	@$(PYTHON) /usr/bin/nosetests --nologcapture --with-coverage unit_tests
+	@$(PYTHON) /usr/bin/nosetests -v --nologcapture --with-coverage unit_tests
 
 functional_test:
 	@echo Starting Amulet tests...

tests/00-setup

@@ -4,11 +4,13 @@ set -ex
 
 sudo add-apt-repository --yes ppa:juju/stable
 sudo apt-get update --yes
-sudo apt-get install --yes python-amulet \
+sudo apt-get install --yes amulet \
                            python-cinderclient \
                            python-distro-info \
                            python-glanceclient \
                            python-heatclient \
                            python-keystoneclient \
+                           python-neutronclient \
                            python-novaclient \
+                           python-pika \
                            python-swiftclient

tests/basic_deployment.py

@@ -456,28 +456,30 @@ class KeystoneBasicDeployment(OpenStackAmuletDeployment):
         set_default = {'use-syslog': 'False'}
         set_alternate = {'use-syslog': 'True'}
 
-        # Config file affected by juju set config change
+        # Services which are expected to restart upon config change,
-        conf_file = '/etc/keystone/keystone.conf'
+        # and corresponding config files affected by the change
-
+        services = {'keystone-all': '/etc/keystone/keystone.conf'}
-        # Services which are expected to restart upon config change
-        services = ['keystone-all']
 
         # Make config change, check for service restarts
         u.log.debug('Making config change on {}...'.format(juju_service))
+        mtime = u.get_sentry_time(sentry)
         self.d.configure(juju_service, set_alternate)
 
         sleep_time = 30
-        for s in services:
+        for s, conf_file in services.iteritems():
             u.log.debug("Checking that service restarted: {}".format(s))
-            if not u.service_restarted(sentry, s,
+            if not u.validate_service_config_changed(sentry, mtime, s,
-                                       conf_file, sleep_time=sleep_time):
+                                                     conf_file,
+                                                     sleep_time=sleep_time):
+
                 self.d.configure(juju_service, set_default)
                 msg = "service {} didn't restart after config change".format(s)
                 amulet.raise_status(amulet.FAIL, msg=msg)
-            sleep_time = 0
 
         self.d.configure(juju_service, set_default)
 
+        u.log.debug('OK')
+
     def test_901_pause_resume(self):
         """Test pause and resume actions."""
         unit_name = "keystone/0"

tests/charmhelpers/contrib/amulet/utils.py

@@ -114,7 +114,7 @@ class AmuletUtils(object):
         # /!\ DEPRECATION WARNING (beisner):
         # New and existing tests should be rewritten to use
         # validate_services_by_name() as it is aware of init systems.
-        self.log.warn('/!\\ DEPRECATION WARNING:  use '
+        self.log.warn('DEPRECATION WARNING:  use '
                       'validate_services_by_name instead of validate_services '
                       'due to init system differences.')
 
@@ -269,33 +269,52 @@ class AmuletUtils(object):
         """Get last modification time of directory."""
         return sentry_unit.directory_stat(directory)['mtime']
 
-    def _get_proc_start_time(self, sentry_unit, service, pgrep_full=False):
+    def _get_proc_start_time(self, sentry_unit, service, pgrep_full=None):
-        """Get process' start time.
+        """Get start time of a process based on the last modification time
+           of the /proc/pid directory.
 
-           Determine start time of the process based on the last modification
+        :sentry_unit:  The sentry unit to check for the service on
-           time of the /proc/pid directory. If pgrep_full is True, the process
+        :service:  service name to look for in process table
-           name is matched against the full command line.
+        :pgrep_full:  [Deprecated] Use full command line search mode with pgrep
-           """
+        :returns:  epoch time of service process start
-        if pgrep_full:
+        :param commands:  list of bash commands
-            cmd = 'pgrep -o -f {}'.format(service)
+        :param sentry_units:  list of sentry unit pointers
-        else:
+        :returns:  None if successful; Failure message otherwise
-            cmd = 'pgrep -o {}'.format(service)
+        """
-        cmd = cmd + '  | grep  -v pgrep || exit 0'
+        if pgrep_full is not None:
-        cmd_out = sentry_unit.run(cmd)
+            # /!\ DEPRECATION WARNING (beisner):
-        self.log.debug('CMDout: ' + str(cmd_out))
+            # No longer implemented, as pidof is now used instead of pgrep.
-        if cmd_out[0]:
+            # https://bugs.launchpad.net/charm-helpers/+bug/1474030
-            self.log.debug('Pid for %s %s' % (service, str(cmd_out[0])))
+            self.log.warn('DEPRECATION WARNING:  pgrep_full bool is no '
-            proc_dir = '/proc/{}'.format(cmd_out[0].strip())
+                          'longer implemented re: lp 1474030.')
-            return self._get_dir_mtime(sentry_unit, proc_dir)
+
+        pid_list = self.get_process_id_list(sentry_unit, service)
+        pid = pid_list[0]
+        proc_dir = '/proc/{}'.format(pid)
+        self.log.debug('Pid for {} on {}: {}'.format(
+            service, sentry_unit.info['unit_name'], pid))
+
+        return self._get_dir_mtime(sentry_unit, proc_dir)
 
     def service_restarted(self, sentry_unit, service, filename,
-                          pgrep_full=False, sleep_time=20):
+                          pgrep_full=None, sleep_time=20):
         """Check if service was restarted.
 
            Compare a service's start time vs a file's last modification time
            (such as a config file for that service) to determine if the service
            has been restarted.
            """
+        # /!\ DEPRECATION WARNING (beisner):
+        # This method is prone to races in that no before-time is known.
+        # Use validate_service_config_changed instead.
+
+        # NOTE(beisner) pgrep_full is no longer implemented, as pidof is now
+        # used instead of pgrep.  pgrep_full is still passed through to ensure
+        # deprecation WARNS.  lp1474030
+        self.log.warn('DEPRECATION WARNING:  use '
+                      'validate_service_config_changed instead of '
+                      'service_restarted due to known races.')
+
         time.sleep(sleep_time)
         if (self._get_proc_start_time(sentry_unit, service, pgrep_full) >=
                 self._get_file_mtime(sentry_unit, filename)):
@@ -304,15 +323,15 @@ class AmuletUtils(object):
             return False
 
     def service_restarted_since(self, sentry_unit, mtime, service,
-                                pgrep_full=False, sleep_time=20,
+                                pgrep_full=None, sleep_time=20,
-                                retry_count=2):
+                                retry_count=2, retry_sleep_time=30):
         """Check if service was been started after a given time.
 
         Args:
           sentry_unit (sentry): The sentry unit to check for the service on
           mtime (float): The epoch time to check against
           service (string): service name to look for in process table
-          pgrep_full (boolean): Use full command line search mode with pgrep
+          pgrep_full: [Deprecated] Use full command line search mode with pgrep
           sleep_time (int): Seconds to sleep before looking for process
           retry_count (int): If service is not found, how many times to retry
 
@@ -321,30 +340,44 @@ class AmuletUtils(object):
                 False if service is older than mtime or if service was
                 not found.
         """
-        self.log.debug('Checking %s restarted since %s' % (service, mtime))
+        # NOTE(beisner) pgrep_full is no longer implemented, as pidof is now
+        # used instead of pgrep.  pgrep_full is still passed through to ensure
+        # deprecation WARNS.  lp1474030
+
+        unit_name = sentry_unit.info['unit_name']
+        self.log.debug('Checking that %s service restarted since %s on '
+                       '%s' % (service, mtime, unit_name))
         time.sleep(sleep_time)
-        proc_start_time = self._get_proc_start_time(sentry_unit, service,
+        proc_start_time = None
-                                                    pgrep_full)
+        tries = 0
-        while retry_count > 0 and not proc_start_time:
+        while tries <= retry_count and not proc_start_time:
-            self.log.debug('No pid file found for service %s, will retry %i '
+            try:
-                           'more times' % (service, retry_count))
+                proc_start_time = self._get_proc_start_time(sentry_unit,
-            time.sleep(30)
+                                                            service,
-            proc_start_time = self._get_proc_start_time(sentry_unit, service,
+                                                            pgrep_full)
-                                                        pgrep_full)
+                self.log.debug('Attempt {} to get {} proc start time on {} '
-            retry_count = retry_count - 1
+                               'OK'.format(tries, service, unit_name))
+            except IOError:
+                # NOTE(beisner) - race avoidance, proc may not exist yet.
+                # https://bugs.launchpad.net/charm-helpers/+bug/1474030
+                self.log.debug('Attempt {} to get {} proc start time on {} '
+                               'failed'.format(tries, service, unit_name))
+                time.sleep(retry_sleep_time)
+                tries += 1
 
         if not proc_start_time:
             self.log.warn('No proc start time found, assuming service did '
                           'not start')
             return False
         if proc_start_time >= mtime:
-            self.log.debug('proc start time is newer than provided mtime'
+            self.log.debug('Proc start time is newer than provided mtime'
-                           '(%s >= %s)' % (proc_start_time, mtime))
+                           '(%s >= %s) on %s (OK)' % (proc_start_time,
+                                                      mtime, unit_name))
             return True
         else:
-            self.log.warn('proc start time (%s) is older than provided mtime '
+            self.log.warn('Proc start time (%s) is older than provided mtime '
-                          '(%s), service did not restart' % (proc_start_time,
+                          '(%s) on %s, service did not '
-                                                             mtime))
+                          'restart' % (proc_start_time, mtime, unit_name))
             return False
 
     def config_updated_since(self, sentry_unit, filename, mtime,
@@ -361,12 +394,15 @@ class AmuletUtils(object):
           bool: True if file was modified more recently than mtime, False if
                 file was modified before mtime,
         """
-        self.log.debug('Checking %s updated since %s' % (filename, mtime))
+        self.log.debug('Checking that %s file updated since '
+                       '%s' % (filename, mtime))
+        unit_name = sentry_unit.info['unit_name']
         time.sleep(sleep_time)
         file_mtime = self._get_file_mtime(sentry_unit, filename)
         if file_mtime >= mtime:
             self.log.debug('File mtime is newer than provided mtime '
-                           '(%s >= %s)' % (file_mtime, mtime))
+                           '(%s >= %s) on %s (OK)' % (file_mtime, mtime,
+                                                      unit_name))
             return True
         else:
             self.log.warn('File mtime %s is older than provided mtime %s'
@@ -374,8 +410,9 @@ class AmuletUtils(object):
             return False
 
     def validate_service_config_changed(self, sentry_unit, mtime, service,
-                                        filename, pgrep_full=False,
+                                        filename, pgrep_full=None,
-                                        sleep_time=20, retry_count=2):
+                                        sleep_time=20, retry_count=2,
+                                        retry_sleep_time=30):
         """Check service and file were updated after mtime
 
         Args:
@@ -383,9 +420,10 @@ class AmuletUtils(object):
           mtime (float): The epoch time to check against
           service (string): service name to look for in process table
           filename (string): The file to check mtime of
-          pgrep_full (boolean): Use full command line search mode with pgrep
+          pgrep_full: [Deprecated] Use full command line search mode with pgrep
-          sleep_time (int): Seconds to sleep before looking for process
+          sleep_time (int): Initial sleep in seconds to pass to test helpers
           retry_count (int): If service is not found, how many times to retry
+          retry_sleep_time (int): Time in seconds to wait between retries
 
         Typical Usage:
             u = OpenStackAmuletUtils(ERROR)
@@ -402,15 +440,25 @@ class AmuletUtils(object):
                 mtime, False if service is older than mtime or if service was
                 not found or if filename was modified before mtime.
         """
-        self.log.debug('Checking %s restarted since %s' % (service, mtime))
+
-        time.sleep(sleep_time)
+        # NOTE(beisner) pgrep_full is no longer implemented, as pidof is now
-        service_restart = self.service_restarted_since(sentry_unit, mtime,
+        # used instead of pgrep.  pgrep_full is still passed through to ensure
-                                                       service,
+        # deprecation WARNS.  lp1474030
-                                                       pgrep_full=pgrep_full,
+
-                                                       sleep_time=0,
+        service_restart = self.service_restarted_since(
-                                                       retry_count=retry_count)
+            sentry_unit, mtime,
-        config_update = self.config_updated_since(sentry_unit, filename, mtime,
+            service,
-                                                  sleep_time=0)
+            pgrep_full=pgrep_full,
+            sleep_time=sleep_time,
+            retry_count=retry_count,
+            retry_sleep_time=retry_sleep_time)
+
+        config_update = self.config_updated_since(
+            sentry_unit,
+            filename,
+            mtime,
+            sleep_time=0)
+
         return service_restart and config_update
 
     def get_sentry_time(self, sentry_unit):

tests/tests.yaml

@@ -8,11 +8,12 @@ sources:
     - ppa:juju/stable
 packages:
     - amulet
-    - python-amulet
     - python-cinderclient
     - python-distro-info
     - python-glanceclient
     - python-heatclient
     - python-keystoneclient
+    - python-neutronclient
     - python-novaclient
+    - python-pika
     - python-swiftclient