Merge lp:~1chb1n/charm-helpers/amulet-svc-restart-race into lp:charm-helpers

[Ryan Beisner]

Add exception handling to the retry logic in service_restarted_since and update _get_proc_start_time to use existing PID helper, addressing bug 1474030.

Add deprecation warn re: service_restarted amulet helper, in favor of validate_service_changed_config.

FYI - The following charm MPs for updated tests are dependent on this C-H change landing first:

https://code.launchpad.net/~1chb1n/charms/trusty/keystone/amulet-svc-check-race-fix/+merge/269501

https://code.launchpad.net/~1chb1n/charms/trusty/neutron-api/next-amulet-update/+merge/263594

https://code.launchpad.net/~1chb1n/charms/trusty/openstack-dashboard/next-amulet-fixup-1507/+merge/268930

https://code.launchpad.net/~1chb1n/charms/trusty/swift-proxy/amulet-update-1508/+merge/268790

[Adam Collard (adam-collard)]

See https://bugs.launchpad.net/charm-helpers/+bug/1474030/comments/2 for explanation on why this isn't sufficient

review: Needs Fixing

[Ryan Beisner (1chb1n)]

See comment on the same bug. Thank you.

[Ryan Beisner (1chb1n)]

Since pgrep -p doesn't work on Precise, and we already have another helper to get a process ID, I've refactored _get_proc_start_time to just use that.

Note that that renders pgrep_full a no-op, and I've also updated the calling helpers to ensure the user receives a deprecation WARN about that, while still ensuring that the default use of the refactored _get_proc_start_time does not result in a deprecation WARN.

[Ryan Beisner (1chb1n)]

FYI, the proposed charm-helpers changes are working well in 2 charms where the race was prevalent, and in 1 charm where the race was seldom seen (keystone):

# openstack-dashboard
https://code.launchpad.net/~1chb1n/charms/trusty/openstack-dashboard/next-amulet-fixup-1507/+merge/268930

# neutron-api
https://code.launchpad.net/~1chb1n/charms/trusty/neutron-api/next-amulet-update/+merge/269302

# keystone
https://code.launchpad.net/~1chb1n/charms/trusty/keystone/amulet-svc-check-race-fix/+merge/269501

[Adam Collard (adam-collard)]

review: Abstain

[Ryan Beisner (1chb1n)]

As we are needing to move forward with this and the child MPs, and we have addressed the original concerns, and Adam isn't in a position to be able to fully review at this time, I'm adding Wolsen back for a review.

PS. Thanks to Adam for raising that issue, so that we could propose something even more robust.

[Billy Olsen (billy-olsen)]

So I've made a few (mostly) editorial comments in-line. I think at the root of whether this should go ahead and go forward or not is based upon whether there exists any implementation dependent upon the pgrep_full behavior. I'm a big +1 on the switch to the use of pidof rather than pgrep because the pgrep implementation allows charm authors to fall into an obscure bug here if they were not careful enough (though admittedly, it'd be due to some lazy coding which could be fixed via being more explicit).

The intention of the pgrep_full flag appears to be to allow amulet test authors to also search script processes rather than just executable names. The -x parameter for pidof allows the same thing to occur. If we define the pgrep_full flag as 'also match script names' rather than the literal interpretation of pgrep_full, then the flag doesn't need to be deprecated.

Most of my in-line comments are based upon the parameter being deprecated. After thinking hard, I'm not entirely sure its required to be deprecated if there is a successful argument in the intent outweighing what is conveyed by the name of the parameter.

review: Needs Fixing

[Ryan Beisner (1chb1n)]

I totally know what you're saying, this is a tricky one for sure. There are other methods there, intended to check the same thing, but they are also broken in some way, and are basically dying on the vine (and without user warnings).

Deprecation reasoning:

The pgrep_full option will be ill-named after switching to pidof behind the scenes.

We could preserve the parameter and just re-plumb it to pidof's -x, but that would be confusing to consume, and no longer self-descriptive, if not actually misleading.

We could add a new option, such as check_scripts_too, and perhaps just aliased pgrep_full for backward compatibility. That would still be confusing in that the pgrep_full option is out of context, and in that we are inviting user error by exposing that control in the first place.

Which brought me to: can we just get to the core of the intention of the method, and make it smart enough to just do-the-right-thing?: "has a service restarted since epoch time nnnnnnnn.nn?"

ie. my_thing_has_restarted(unit, service, since_epoch_time) It should be that simple, and yet still reliable.

We are already using pidof -x reliably in an existing is_my_service_running helper (-x always on).

And that is the journey of my arrival at: just deprecate it and announce in any case that it is defined.

I did backwards-compatibility spot-checking of this branch by syncing it into multiple charms which previously used the old method with pgrep_full defined (some with True, some with False, some not defined). The proposed refactor and deprecation just worked in all cases that I checked, resolved the race issues, and gave deprecation warnings to boot. So, in that, it reaches my initial goal of fixing this in a way that would resolve those issues with a simple c-h re-sync, without having to modify test code.

I recognize that there is a remote possibility that someone outside our awareness is using that helper function, and this could possibly break them. I think we've minimized that risk, and we've given user feedback appropriately. That's always debatable of course.

So..

What I want to avoid is adding yet-another rewrite of a my_thing_has_restarted helper method to go along with the other 2 that are present, in-use and racy. But actually, it may be a better and cleaner helper if we were to do that (from scratch). Then we could just give YMMV WARNs in the known-problematic ones.

Ideas?

[Ryan Beisner (1chb1n)]

See replies inline. The more I look over this, and it's ancestors, the more I want to just revert all of this and add a new helper that just works.

Talk me out of doing that?

[Billy Olsen (billy-olsen)]

Okay, let's go deprecation warnings for the parameter, which is where you went anyway. I probably should not have gone in the direction that I went in with the possibility of not deprecating the parameter. The deprecation warnings serve to notify charm authors but also to allow for this to be a drop-in replacement with as little backwards compatibility issues as possible, so it gets my upvote for that.

Please do NOT add a new option for checking scripts and just use the pidof -x. By deprecating the pgrep_full option we're favoring the desirable approach. If someone can make a really strong use case for adding another flag lets consider adding the flag or something at that point.

I haven't gone through all the ancestry for the method yet, but if we add yet another way then it becomes to confusing as to which method to use. So let's just do the right thing and fix the behavior to work as advertised/expected as this MP is doing.

[Ryan Beisner (1chb1n)]

Thanks again for the good questions and replies and advice.

Add'l replies in-line.

[Billy Olsen (billy-olsen)]

Ah, thanks for the updates Ryan - I think we're now fully on the same page. Just a few minor edits then I guess and it gets my +1.

[lp:~1chb1n/charm-helpers/amulet-svc-restart-race]

438. By Ryan Beisner on 2015-09-02

update comments, pgrep_full conditional

[Billy Olsen (billy-olsen)]

Thanks for making the changes. LGTM - I added an additional comment for follow up later but it shouldn't hold this MP up in my mind.

review: Approve

[Ryan Beisner (1chb1n)]

Replied inline. Thanks again!

[Billy Olsen (billy-olsen)]

One more back at ya. Let's get it merged.

[Ryan Beisner (1chb1n)]

Thanks again, are we ready to land this, so we can also land the related charm test updates?

[Billy Olsen (billy-olsen)]

Yes, I think this is ready to be landed.

=== modified file 'charmhelpers/contrib/amulet/utils.py'
--- charmhelpers/contrib/amulet/utils.py	2015-08-17 10:47:36 +0000
+++ charmhelpers/contrib/amulet/utils.py	2015-09-02 01:09:48 +0000
@@ -114,7 +114,7 @@
         # /!\ 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 @@
         """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):
-        """Get process' start time.
-
-           Determine start time of the process based on the last modification
-           time of the /proc/pid directory. If pgrep_full is True, the process
-           name is matched against the full command line.
-           """
-        if pgrep_full:
-            cmd = 'pgrep -o -f {}'.format(service)
-        else:
-            cmd = 'pgrep -o {}'.format(service)
-        cmd = cmd + '  | grep  -v pgrep || exit 0'
-        cmd_out = sentry_unit.run(cmd)
-        self.log.debug('CMDout: ' + str(cmd_out))
-        if cmd_out[0]:
-            self.log.debug('Pid for %s %s' % (service, str(cmd_out[0])))
-            proc_dir = '/proc/{}'.format(cmd_out[0].strip())
-            return self._get_dir_mtime(sentry_unit, proc_dir)
+    def _get_proc_start_time(self, sentry_unit, service, pgrep_full=None):
+        """Get start time of a process based on the last modification time
+           of the /proc/pid directory.
+
+        :sentry_unit:  The sentry unit to check for the service on
+        :service:  service name to look for in process table
+        :pgrep_full:  [Deprecated] Use full command line search mode with pgrep
+        :returns:  epoch time of service process start
+        :param commands:  list of bash commands
+        :param sentry_units:  list of sentry unit pointers
+        :returns:  None if successful; Failure message otherwise
+        """
+        if pgrep_full is not None:
+            # /!\ DEPRECATION WARNING (beisner):
+            # No longer implemented, as pidof is now used instead of pgrep.
+            # https://bugs.launchpad.net/charm-helpers/+bug/1474030
+            self.log.warn('DEPRECATION WARNING:  pgrep_full bool is no '
+                          'longer implemented re: lp 1474030.')
+
+        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 @@
             return False
 
     def service_restarted_since(self, sentry_unit, mtime, service,
-                                pgrep_full=False, sleep_time=20,
-                                retry_count=2):
+                                pgrep_full=None, sleep_time=20,
+                                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 @@
                 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,
-                                                    pgrep_full)
-        while retry_count > 0 and not proc_start_time:
-            self.log.debug('No pid file found for service %s, will retry %i '
-                           'more times' % (service, retry_count))
-            time.sleep(30)
-            proc_start_time = self._get_proc_start_time(sentry_unit, service,
-                                                        pgrep_full)
-            retry_count = retry_count - 1
+        proc_start_time = None
+        tries = 0
+        while tries <= retry_count and not proc_start_time:
+            try:
+                proc_start_time = self._get_proc_start_time(sentry_unit,
+                                                            service,
+                                                            pgrep_full)
+                self.log.debug('Attempt {} to get {} proc start time on {} '
+                               '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'
-                           '(%s >= %s)' % (proc_start_time, mtime))
+            self.log.debug('Proc start time is newer than provided 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 '
-                          '(%s), service did not restart' % (proc_start_time,
-                                                             mtime))
+            self.log.warn('Proc start time (%s) is older than provided mtime '
+                          '(%s) on %s, service did not '
+                          'restart' % (proc_start_time, mtime, unit_name))
             return False
 
     def config_updated_since(self, sentry_unit, filename, mtime,
@@ -361,12 +394,15 @@
           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 @@
             return False
 
     def validate_service_config_changed(self, sentry_unit, mtime, service,
-                                        filename, pgrep_full=False,
-                                        sleep_time=20, retry_count=2):
+                                        filename, pgrep_full=None,
+                                        sleep_time=20, retry_count=2,
+                                        retry_sleep_time=30):
         """Check service and file were updated after mtime
 
         Args:
@@ -383,9 +420,10 @@
           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
-          sleep_time (int): Seconds to sleep before looking for process
+          pgrep_full: [Deprecated] Use full command line search mode with pgrep
+          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 @@
                 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)
-        service_restart = self.service_restarted_since(sentry_unit, mtime,
-                                                       service,
-                                                       pgrep_full=pgrep_full,
-                                                       sleep_time=0,
-                                                       retry_count=retry_count)
-        config_update = self.config_updated_since(sentry_unit, filename, mtime,
-                                                  sleep_time=0)
+
+        # 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
+
+        service_restart = self.service_restarted_since(
+            sentry_unit, mtime,
+            service,
+            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):