yandex-tank/tankcore.py

""" The central part of the tool: Core """
from ConfigParser import NoSectionError
import ConfigParser
import datetime
import errno
import itertools
import logging
import os
import re
import select
import shlex
import shutil
import subprocess
import sys
import tempfile
import time
import traceback
import fnmatch
import psutil


def log_stdout_stderr(log, stdout, stderr, comment=""):
    """
    This function polls stdout and stderr streams and writes their contents to log
    """
    readable = select.select([stdout], [], [], 0)[0]
    if stderr:
        exceptional = select.select([stderr], [], [], 0)[0]
    else:
        exceptional = []

    log.debug("Selected: %s, %s", readable, exceptional)

    for handle in readable:
        line = handle.read()
        readable.remove(handle)
        if line:
            log.debug("%s stdout: %s", comment, line.strip())

    for handle in exceptional:
        line = handle.read()
        exceptional.remove(handle)
        if line:
            log.warn("%s stderr: %s", comment, line.strip())


def expand_to_milliseconds(str_time):
    """
    converts 1d2s into milliseconds
    """
    return expand_time(str_time, 'ms', 1000)


def expand_to_seconds(str_time):
    """
    converts 1d2s into seconds
    """
    return expand_time(str_time, 's', 1)


def expand_time(str_time, default_unit='s', multiplier=1):
    """
    helper for above functions
    """
    parser = re.compile('(\d+)([a-zA-Z]*)')
    parts = parser.findall(str_time)
    result = 0.0
    for value, unit in parts:
        value = int(value)
        unit = unit.lower()
        if unit == '':
            unit = default_unit

        if unit == 'ms':
            result += value * 0.001
            continue
        elif unit == 's':
            result += value
            continue
        elif unit == 'm':
            result += value * 60
            continue
        elif unit == 'h':
            result += value * 60 * 60
            continue
        elif unit == 'd':
            result += value * 60 * 60 * 24
            continue
        elif unit == 'w':
            result += value * 60 * 60 * 24 * 7
            continue
        else:
            raise ValueError(
                "String contains unsupported unit %s: %s" % (unit, str_time))
    return int(result * multiplier)


def pid_exists(pid):
    """Check whether pid exists in the current process table."""
    if pid < 0:
        return False
    try:
        os.kill(pid, 0)
    except OSError, exc:
        logging.debug("No process[%s]: %s", exc.errno, exc)
        return exc.errno == errno.EPERM
    else:
        p = psutil.Process(pid)
        return p.status != psutil.STATUS_ZOMBIE


def execute(cmd, shell=False, poll_period=1.0, catch_out=False):
    """
    Wrapper for Popen
    """
    log = logging.getLogger(__name__)
    log.debug("Starting: %s", cmd)

    stdout = ""
    stderr = ""

    if not shell and isinstance(cmd, basestring):
        cmd = shlex.split(cmd)

    if catch_out:
        process = subprocess.Popen(
            cmd, shell=shell, stderr=subprocess.PIPE, stdout=subprocess.PIPE, close_fds=True)
    else:
        process = subprocess.Popen(cmd, shell=shell, close_fds=True)

    while process.poll() is None:
        log.debug("Waiting for process to finish: %s", process)
        time.sleep(poll_period)

    if catch_out:
        for line in process.stderr.readlines():
            stderr += line
            log.warn(line.strip())
        for line in process.stdout.readlines():
            stdout += line
            log.debug(line.strip())

    retcode = process.poll()
    log.debug("Process exit code: %s", retcode)
    return retcode, stdout, stderr


def splitstring(string):
    """
    >>> string = 'apple orange "banana tree" green'
    >>> splitstring(string)
    ['apple', 'orange', 'green', '"banana tree"']
    """
    patt = re.compile(r'"[\w ]+"')
    if patt.search(string):
        quoted_item = patt.search(string).group()
        newstring = patt.sub('', string)
        return newstring.split() + [quoted_item]
    else:
        return string.split()


def pairs(lst):
    """
    Iterate over pairs in the list
    """
    return itertools.izip(lst[::2], lst[1::2])


class TankCore:
    """
    JMeter + dstat inspired :)
    """
    SECTION = 'tank'
    PLUGIN_PREFIX = 'plugin_'
    PID_OPTION = 'pid'
    LOCK_DIR = '/var/lock'

    def __init__(self):
        self.log = logging.getLogger(__name__)
        self.config = ConfigManager()
        self.plugins = {}
        self.artifacts_dir = None
        self.artifact_files = {}
        self.plugins_order = []
        self.artifacts_base_dir = '.'
        self.manual_start = False
        self.scheduled_start = None
        self.interrupted = False
        self.lock_file = None
        self.flush_config_to = None
        self.lock_dir = None
        self.set_option(self.SECTION, self.PID_OPTION, str(os.getpid()))

    def get_available_options(self):
        return ["artifacts_base_dir", "artifacts_dir", "flush_config_to"]

    def load_configs(self, configs):
        """        Tells core to load configs set into options storage        """
        self.log.info("Loading configs...")
        for fname in configs:
            if not os.path.isfile(fname):
                # can't raise exception, since ~/.yandex-tank may not exist
                logging.debug("Config file not found: %s", fname)

        self.config.load_files(configs)
        dotted_options = []
        for option, value in self.config.get_options(self.SECTION):
            if '.' in option:
                dotted_options += [option + '=' + value]
        self.apply_shorthand_options(dotted_options, self.SECTION)
        self.config.flush()
        self.add_artifact_file(self.config.file)
        self.set_option(self.SECTION, self.PID_OPTION, str(os.getpid()))
        self.flush_config_to = self.get_option(
            self.SECTION, "flush_config_to", "")
        if self.flush_config_to:
            self.config.flush(self.flush_config_to)

    def load_plugins(self):
        """        Tells core to take plugin options and instantiate plugin classes        """
        self.log.info("Loading plugins...")

        self.artifacts_base_dir = os.path.expanduser(
            self.get_option(self.SECTION, "artifacts_base_dir", self.artifacts_base_dir))
        self.artifacts_dir = self.get_option(self.SECTION, "artifacts_dir", self.artifacts_dir)
        if self.artifacts_dir:
            self.artifacts_dir = os.path.expanduser(self.artifacts_dir)

        options = self.config.get_options(self.SECTION, self.PLUGIN_PREFIX)
        for (plugin_name, plugin_path) in options:
            if not plugin_path:
                self.log.debug(
                    "Seems the plugin '%s' was disabled", plugin_name)
                continue
            instance = self.__load_plugin(plugin_name, plugin_path)
            key = os.path.realpath(instance.get_key())
            self.plugins[key] = instance
            self.plugins_order.append(key)

        self.log.debug("Plugin instances: %s", self.plugins)
        self.log.debug("Plugins order: %s", self.plugins_order)

    def __load_plugin(self, name, path):
        """        Load single plugin using 'exec' statement        """
        self.log.debug("Loading plugin %s from %s", name, path)
        for basedir in [''] + sys.path:
            if basedir:
                new_dir = basedir + '/' + path
            else:
                new_dir = path
            if os.path.exists(new_dir):
                new_dir = os.path.dirname(new_dir)
                if new_dir not in sys.path:
                    self.log.debug('Append to path: %s', new_dir)
                    sys.path.append(new_dir)
        res = None
        classname = os.path.basename(path)[:-3]
        self.log.debug("sys.path: %s", sys.path)
        exec ("import " + classname)
        script = "res=" + classname + "." + classname + "Plugin(self)"
        self.log.debug("Exec: " + script)
        exec script
        self.log.debug("Instantiated: %s", res)
        return res

    def plugins_configure(self):
        """        Call configure() on all plugins        """
        if not os.path.exists(self.artifacts_base_dir):
            os.makedirs(self.artifacts_base_dir)
            os.chmod(self.artifacts_base_dir, 0755)

        self.log.info("Configuring plugins...")
        for plugin_key in self.plugins_order:
            plugin = self.__get_plugin_by_key(plugin_key)
            self.log.debug("Configuring %s", plugin)
            plugin.configure()
            self.config.flush()
        if self.flush_config_to:
            self.config.flush(self.flush_config_to)

    def plugins_prepare_test(self):
        """ Call prepare_test() on all plugins        """
        self.log.info("Preparing test...")
        for plugin_key in self.plugins_order:
            plugin = self.__get_plugin_by_key(plugin_key)
            self.log.debug("Preparing %s", plugin)
            plugin.prepare_test()
        if self.flush_config_to:
            self.config.flush(self.flush_config_to)

    def plugins_start_test(self):
        """        Call start_test() on all plugins        """
        self.log.info("Starting test...")
        for plugin_key in self.plugins_order:
            plugin = self.__get_plugin_by_key(plugin_key)
            self.log.debug("Starting %s", plugin)
            plugin.start_test()
        if self.flush_config_to:
            self.config.flush(self.flush_config_to)

    def wait_for_finish(self):
        """        Call is_test_finished() on all plugins 'till one of them initiates exit        """

        self.log.info("Waiting for test to finish...")
        if not self.plugins:
            raise RuntimeError("It's strange: we have no plugins loaded...")

        while not self.interrupted:
            begin_time = time.time()
            for plugin_key in self.plugins_order:
                plugin = self.__get_plugin_by_key(plugin_key)
                self.log.debug("Polling %s", plugin)
                retcode = plugin.is_test_finished()
                if retcode >= 0:
                    return retcode
            end_time = time.time()
            diff = end_time - begin_time
            self.log.debug("Polling took %s", diff)
            # screen refresh every 0.5 s
            if diff < 0.5:
                time.sleep(0.5 - diff)
        return 1

    def plugins_end_test(self, retcode):
        """        Call end_test() on all plugins        """
        self.log.info("Finishing test...")

        for plugin_key in self.plugins_order:
            plugin = self.__get_plugin_by_key(plugin_key)
            self.log.debug("Finalize %s", plugin)
            try:
                self.log.debug("RC before: %s", retcode)
                plugin.end_test(retcode)
                self.log.debug("RC after: %s", retcode)
            except Exception, ex:
                self.log.error("Failed finishing plugin %s: %s", plugin, ex)
                self.log.debug(
                    "Failed finishing plugin: %s", traceback.format_exc(ex))
                if not retcode:
                    retcode = 1

        if self.flush_config_to:
            self.config.flush(self.flush_config_to)
        return retcode

    def plugins_post_process(self, retcode):
        """
        Call post_process() on all plugins
        """
        self.log.info("Post-processing test...")

        for plugin_key in self.plugins_order:
            plugin = self.__get_plugin_by_key(plugin_key)
            self.log.debug("Post-process %s", plugin)
            try:
                self.log.debug("RC before: %s", retcode)
                retcode = plugin.post_process(retcode)
                self.log.debug("RC after: %s", retcode)
            except Exception, ex:
                self.log.error(
                    "Failed post-processing plugin %s: %s", plugin, ex)
                self.log.debug(
                    "Failed post-processing plugin: %s", traceback.format_exc(ex))
                del self.plugins[plugin_key]
                if not retcode:
                    retcode = 1

        if self.flush_config_to:
            self.config.flush(self.flush_config_to)

        self.__collect_artifacts()

        return retcode

    def __collect_artifacts(self):
        self.log.debug("Collecting artifacts")
        if not self.artifacts_dir:
            date_str = datetime.datetime.now().strftime("%Y-%m-%d_%H-%M-%S.")
            self.artifacts_dir = tempfile.mkdtemp(
                "", date_str, self.artifacts_base_dir)
        if not os.path.isdir(self.artifacts_dir):
            os.makedirs(self.artifacts_dir)

        os.chmod(self.artifacts_dir, 0755)

        self.log.info("Artifacts dir: %s", self.artifacts_dir)
        for filename, keep in self.artifact_files.items():
            try:
                self.__collect_file(filename, keep)
            except Exception, ex:
                self.log.warn("Failed to collect file %s: %s", filename, ex)

    def get_option(self, section, option, default=None):
        """
        Get an option from option storage
        """
        if not self.config.config.has_section(section):
            self.log.debug("No section '%s', adding", section)
            self.config.config.add_section(section)

        try:
            value = self.config.config.get(section, option).strip()
        except ConfigParser.NoOptionError as ex:
            if default is not None:
                default = str(default)
                self.config.config.set(section, option, default)
                self.config.flush()
                value = default.strip()
            else:
                self.log.warn("Mandatory option %s was not found in section %s", option, section)
                raise ex

        if len(value) > 1 and value[0] == '`' and value[-1] == '`':
            self.log.debug("Expanding shell option %s", value)
            retcode, stdout, stderr = execute(value[1:-1], True, 0.1, True)
            if retcode or stderr:
                raise ValueError(
                    "Error expanding option %s, RC: %s" % (value, retcode))
            value = stdout.strip()

        return value

    def set_option(self, section, option, value):
        """
        Set an option in storage
        """
        if not self.config.config.has_section(section):
            self.config.config.add_section(section)
        self.config.config.set(section, option, value)
        self.config.flush()

    def get_plugin_of_type(self, needle):
        """
        Retrieve a plugin of desired class, KeyError raised otherwise
        """
        self.log.debug("Searching for plugin: %s", needle)
        key = os.path.realpath(needle.get_key())

        return self.__get_plugin_by_key(key)

    def __get_plugin_by_key(self, key):
        """
        Get plugin from loaded by its key
        """
        if key in self.plugins.keys():
            return self.plugins[key]

        ext = os.path.splitext(key)[1].lower()

        if ext == '.py' and key + 'c' in self.plugins.keys():  # .py => .pyc
            return self.plugins[key + 'c']

        if ext == '.pyc' and key[:-1] in self.plugins.keys():  # .pyc => .py:
            return self.plugins[key[:-1]]

        raise KeyError("Requested plugin type not found: %s" % key)

    def __collect_file(self, filename, keep_original=False):
        """
        Move or copy single file to artifacts dir
        """
        if not self.artifacts_dir:
            self.log.warning("No artifacts dir configured")
            return

        dest = self.artifacts_dir + '/' + os.path.basename(filename)
        self.log.debug("Collecting file: %s to %s", filename, dest)
        if not filename or not os.path.exists(filename):
            self.log.warning("File not found to collect: %s", filename)
            return

        if os.path.exists(dest):
            # FIXME: 3 find a way to store artifacts anyway
            self.log.warning("File already exists: %s", dest)
            return

        if keep_original:
            shutil.copy(filename, self.artifacts_dir)
        else:
            shutil.move(filename, self.artifacts_dir)

        os.chmod(dest, 0644)

    def add_artifact_file(self, filename, keep_original=False):
        """
        Add file to be stored as result artifact on post-process phase
        """
        if filename:
            logging.debug("Adding artifact file to collect (keep=%s): %s", keep_original, filename)
            self.artifact_files[filename] = keep_original

    def apply_shorthand_options(self, options, default_section='DEFAULT'):
        for option_str in options:
            try:
                section = option_str[:option_str.index('.')]
                option = option_str[option_str.index('.') + 1:option_str.index('=')]
            except ValueError:
                section = default_section
                option = option_str[:option_str.index('=')]
            value = option_str[option_str.index('=') + 1:]
            self.log.debug(
                "Override option: %s => [%s] %s=%s", option_str, section, option, value)
            self.set_option(section, option, value)

    def get_lock_dir(self):
        if not self.lock_dir:
            self.lock_dir = self.get_option(self.SECTION, "lock_dir", self.LOCK_DIR)

        return os.path.expanduser(self.lock_dir)

    def get_lock(self, force=False):
        if not force and self.__there_is_locks():
            raise RuntimeError("There is lock files")

        fh, self.lock_file = tempfile.mkstemp(
            '.lock', 'lunapark_', self.get_lock_dir())
        os.close(fh)
        os.chmod(self.lock_file, 0644)
        self.config.file = self.lock_file
        self.config.flush()

    def release_lock(self):
        self.config.file = None
        if self.lock_file and os.path.exists(self.lock_file):
            self.log.debug("Releasing lock: %s", self.lock_file)
            os.remove(self.lock_file)

    def __there_is_locks(self):
        retcode = False
        lock_dir = self.get_lock_dir()
        for filename in os.listdir(lock_dir):
            if fnmatch.fnmatch(filename, 'lunapark_*.lock'):
                full_name = os.path.join(lock_dir, filename)
                self.log.warn("Lock file present: %s", full_name)

                try:
                    info = ConfigParser.ConfigParser()
                    info.read(full_name)
                    pid = info.get(TankCore.SECTION, self.PID_OPTION)
                    if not pid_exists(int(pid)):
                        self.log.debug(
                            "Lock PID %s not exists, ignoring and trying to remove", pid)
                        try:
                            os.remove(full_name)
                        except Exception, exc:
                            self.log.debug(
                                "Failed to delete lock %s: %s", full_name, exc)
                    else:
                        retcode = True
                except Exception, exc:
                    self.log.warn(
                        "Failed to load info from lock %s: %s", full_name, exc)
                    retcode = True
        return retcode

    def mkstemp(self, suffix, prefix, directory=None):
        """
        Generate temp file name in artifacts base dir
        and close temp file handle
        """
        if not directory:
            directory = self.artifacts_base_dir
        fd, fname = tempfile.mkstemp(suffix, prefix, directory)
        os.close(fd)
        os.chmod(fname, 0644)  # FIXME: chmod to parent dir's mode?
        return fname


class ConfigManager:
    """    Option storage class    """

    def __init__(self):
        self.file = None
        self.log = logging.getLogger(__name__)
        self.config = ConfigParser.ConfigParser()

    def load_files(self, configs):
        """         Read configs set into storage        """
        self.log.debug("Reading configs: %s", configs)
        try:
            self.config.read(configs)
        except Exception as ex:
            self.log.error("Can't load configs: %s", ex)
            raise ex

    def flush(self, filename=None):
        """        Flush current stat to file        """
        if not filename:
            filename = self.file

        if filename:
            self.log.debug("Flushing config to: %s", filename)
            handle = open(filename, 'wb')
            self.config.write(handle)
            handle.close()

    def get_options(self, section, prefix=''):
        """        Get options list with requested prefix        """
        res = []
        self.log.debug(
            "Looking in section '%s' for options starting with '%s'", section, prefix)
        try:
            for option in self.config.options(section):
                self.log.debug("Option: %s", option)
                if not prefix or option.find(prefix) == 0:
                    self.log.debug("Option: %s matched", option)
                    res += [
                        (option[len(prefix):], self.config.get(section, option))]
        except NoSectionError, ex:
            self.log.debug("No section: %s", ex)

        self.log.debug("Found options: %s", res)
        return res

    def find_sections(self, prefix):
        """ return sections with specified prefix """
        res = []
        for section in self.config.sections():
            if section.startswith(prefix):
                res.append(section)
        return res


class AbstractPlugin:
    """    Parent class for all plugins/modules    """

    SECTION = 'DEFAULT'

    @staticmethod
    def get_key():
        """        Get dictionary key for plugin, should point to __file__ magic constant        """
        raise TypeError("Abstract method needs to be overridden")

    def __init__(self, core):
        """

        @type core: TankCore
        """
        self.log = logging.getLogger(__name__)
        self.core = core

    def configure(self):
        """        A stage to read config values and instantiate objects        """
        pass

    def prepare_test(self):
        """        Test preparation tasks        """
        pass

    def start_test(self):
        """        Launch test process        """
        pass

    def is_test_finished(self):
        """        Polling call, if result differs from -1 then test end will be triggeted        """
        return -1

    def end_test(self, retcode):
        """        Stop processes launched at 'start_test', change return code if necessary        """
        return retcode

    def post_process(self, retcode):
        """        Post-process test data        """
        return retcode

    def get_option(self, option_name, default_value=None):
        """        Wrapper to get option from plugins' section        """
        return self.core.get_option(self.SECTION, option_name, default_value)

    def set_option(self, option_name, value):
        """        Wrapper to set option to plugins' section        """
        return self.core.set_option(self.SECTION, option_name, value)

    def get_available_options(self):
        """ returns array containing known options for plugin """
        return []

    def get_multiline_option(self, option_name, default_value=None):
        if default_value is not None:
            default = ' '.join(default_value)
        else:
            default = None
        value = self.get_option(option_name, default)
        if value:
            return (' '.join(value.split("\n"))).split(' ')
        else:
            return ()