ceph/teuthology/task/mon_clock_skew_check.py

import logging
import contextlib
import ceph_manager
import time
import gevent
from teuthology import misc as teuthology

log = logging.getLogger(__name__)

class ClockSkewCheck:
  """
  Periodically check if there are any clock skews among the monitors in the
  quorum. By default, assume no skews are supposed to exist; that can be
  changed using the 'expect-skew' option. If 'fail-on-skew' is set to false,
  then we will always succeed and only report skews if any are found.

  This class does not spawn a thread. It assumes that, if that is indeed
  wanted, it should be done by a third party (for instance, the task using
  this class). We intend it as such in order to reuse this class if need be.

  This task accepts the following options:

   interval     amount of seconds to wait in-between checks. (default: 30.0)
   max-skew     maximum skew, in seconds, that is considered tolerable before
                issuing a warning. (default: 0.05)
   expect-skew  'true' or 'false', to indicate whether to expect a skew during
                the run or not. If 'true', the test will fail if no skew is
                found, and succeed if a skew is indeed found; if 'false', it's
                the other way around. (default: false)
   never-fail   Don't fail the run if a skew is detected and we weren't
                expecting it, or if no skew is detected and we were expecting
                it. (default: False)

   at-least-once          Runs at least once, even if we are told to stop.
                          (default: True)
   at-least-once-timeout  If we were told to stop but we are attempting to
                          run at least once, timeout after this many seconds.
                          (default: 600)

  Example:
    Expect a skew higher than 0.05 seconds, but only report it without failing
    the teuthology run.

    - mon_clock_skew_check:
        interval: 30
        max-skew: 0.05
        expect_skew: true
        never-fail: true
  """

  def __init__(self, ctx, manager, config, logger):
    self.ctx = ctx
    self.manager = manager;

    self.stopping = False
    self.logger = logger
    self.config = config

    if self.config is None:
      self.config = dict()

    self.check_interval = float(self.config.get('interval', 30.0))
    self.max_skew = float(self.config.get('max-skew', 0.05))
    self.expect_skew = self.config.get('expect-skew', False)
    self.never_fail = self.config.get('never-fail', False)
    self.at_least_once = self.config.get('at-least-once', True)
    self.at_least_once_timeout = self.config.get('at-least-once-timeout', 600.0)

  def info(self, x):
    self.logger.info(x)

  def warn(self, x):
    self.logger.warn(x)

  def debug(self, x):
    self.logger.debug(x)

  def finish(self):
    self.stopping = True

  def sleep_interval(self):
    if self.check_interval > 0.0:
      self.debug('sleeping for {s} seconds'.format(
        s=self.check_interval))
      time.sleep(self.check_interval)

  def print_skews(self, skews):
    total = len(skews)
    if total > 0:
      self.info('---------- found {n} skews ----------'.format(n=total))
      for mon_id,values in skews.iteritems():
        self.info('mon.{id}: {v}'.format(id=mon_id,v=values))
      self.info('-------------------------------------')
    else:
      self.info('---------- no skews were found ----------')

  def do_check(self):
    self.info('start checking for clock skews')
    skews = dict()
    ran_once = False
    started_on = None

    while not self.stopping or (self.at_least_once and not ran_once):

      if self.at_least_once and not ran_once and self.stopping:
        if started_on is None:
          self.info('kicking-off timeout (if any)')
          started_on = time.time()
        elif self.at_least_once_timeout > 0.0:
          assert time.time() - started_on < self.at_least_once_timeout, \
              'failed to obtain a timecheck before timeout expired'

      quorum_size = len(teuthology.get_mon_names(self.ctx))
      self.manager.wait_for_mon_quorum_size(quorum_size)

      health = self.manager.get_mon_health(True)
      timechecks = health['timechecks']

      clean_check = False

      if timechecks['round_status'] == 'finished':
        assert (timechecks['round'] % 2) == 0, \
            'timecheck marked as finished but round ' \
            'disagrees (r {r})'.format(
                r=timechecks['round'])
        clean_check = True
      else:
        assert timechecks['round_status'] == 'on-going', \
            'timecheck status expected \'on-going\' ' \
            'but found \'{s}\' instead'.format(
                s=timechecks['round_status'])
        if 'mons' in timechecks.keys() and len(timechecks['mons']) > 1:
          self.info('round still on-going, but there are available reports')
        else:
          self.info('no timechecks available just yet')
          self.sleep_interval()
          continue

      assert len(timechecks['mons']) > 1, \
          'there are not enough reported timechecks; ' \
          'expected > 1 found {n}'.format(n=len(timechecks['mons']))

      for check in timechecks['mons']:
        mon_skew = float(check['skew'])
        mon_health = check['health']
        mon_id = check['name']
        if abs(mon_skew) > self.max_skew:
          assert mon_health == 'HEALTH_WARN', \
              'mon.{id} health is \'{health}\' but skew {s} > max {ms}'.format(
                  id=mon_id,s=abs(mon_skew),ms=self.max_skew)

          log_str = 'mon.{id} with skew {s} > max {ms}'.format(
            id=mon_id,s=abs(mon_skew),ms=self.max_skew)

          """ add to skew list """
          details = check['details']
          skews[mon_id] = {'skew': mon_skew, 'details': details}

          if self.expect_skew:
            self.info('expected skew: {str}'.format(str=log_str))
          else:
            self.warn('unexpected skew: {str}'.format(str=log_str))

      if clean_check or (self.expect_skew and len(skews) > 0):
        ran_once = True
        self.print_skews(skews)
      self.sleep_interval()

    total = len(skews)
    self.print_skews(skews)

    error_str = ''
    found_error = False

    if self.expect_skew:
      if total == 0:
        error_str = 'We were expecting a skew, but none was found!'
        found_error = True
    else:
      if total > 0:
        error_str = 'We were not expecting a skew, but we did find it!'
        found_error = True

    if found_error:
      self.info(error_str)
      if not self.never_fail:
        assert False, error_str

@contextlib.contextmanager
def task(ctx, config):
  """
  Use clas ClockSkewCheck to check for clock skews on the monitors.
  This task will spawn a thread running ClockSkewCheck's do_check().

  All the configuration will be directly handled by ClockSkewCheck,
  so please refer to the class documentation for further information.
  """
  if config is None:
    config = {}
  assert isinstance(config, dict), \
      'mon_clock_skew_check task only accepts a dict for configuration'
  log.info('Beginning mon_clock_skew_check...')
  first_mon = teuthology.get_first_mon(ctx, config)
  (mon,) = ctx.cluster.only(first_mon).remotes.iterkeys()
  manager = ceph_manager.CephManager(
      mon,
      ctx=ctx,
      logger=log.getChild('ceph_manager'),
      )

  skew_check = ClockSkewCheck(ctx,
      manager, config,
      logger=log.getChild('mon_clock_skew_check'))
  skew_check_thread = gevent.spawn(skew_check.do_check)
  try:
    yield
  finally:
    log.info('joining mon_clock_skew_check')
    skew_check.finish()
    skew_check_thread.get()