openvswitch/python/ovs/vlog.py

# Copyright (c) 2011, 2012, 2013 Nicira, Inc.
#
# Licensed under the Apache License, Version 2.0 (the "License");
# you may not use this file except in compliance with the License.
# You may obtain a copy of the License at:
#
#     http://www.apache.org/licenses/LICENSE-2.0
#
# Unless required by applicable law or agreed to in writing, software
# distributed under the License is distributed on an "AS IS" BASIS,
# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
# See the License for the specific language governing permissions and
# limitations under the License.

import datetime
import logging
import logging.handlers
import os
import re
import socket
import sys
import threading

import ovs.dirs
import ovs.unixctl
import ovs.util

DESTINATIONS = {"console": "info", "file": "info", "syslog": "info"}
PATTERNS = {
    "console": "%D{%Y-%m-%dT%H:%M:%SZ}|%05N|%c%T|%p|%m",
    "file": "%D{%Y-%m-%dT%H:%M:%S.###Z}|%05N|%c%T|%p|%m",
    "syslog": "ovs|%05N|%c%T|%p|%m",
}
LEVELS = {
    "dbg": logging.DEBUG,
    "info": logging.INFO,
    "warn": logging.WARNING,
    "err": logging.ERROR,
    "emer": logging.CRITICAL,
    "off": logging.CRITICAL
}
FACILITIES = ['auth', 'authpriv', 'cron', 'daemon', 'ftp', 'kern', 'lpr',
              'mail', 'news', 'syslog', 'user', 'uucp', 'local0', 'local1',
              'local2', 'local3', 'local4', 'local5', 'local6', 'local7']
syslog_facility = "daemon"
syslog_handler = ''


def get_level(level_str):
    return LEVELS.get(level_str.lower())


class Vlog:
    __inited = False
    __msg_num = 0
    __start_time = 0
    __mfl = {}  # Module -> destination -> level
    __log_file = None
    __file_handler = None
    __log_patterns = PATTERNS

    def __init__(self, name):
        """Creates a new Vlog object representing a module called 'name'.  The
        created Vlog object will do nothing until the Vlog.init() static method
        is called.  Once called, no more Vlog objects may be created."""

        assert not Vlog.__inited
        self.name = name.lower()
        if name not in Vlog.__mfl:
            Vlog.__mfl[self.name] = DESTINATIONS.copy()

    def __log(self, level, message, **kwargs):
        if not Vlog.__inited:
            return

        level_num = LEVELS.get(level.lower(), logging.DEBUG)
        msg_num = Vlog.__msg_num
        Vlog.__msg_num += 1

        for f, f_level in Vlog.__mfl[self.name].iteritems():
            f_level = LEVELS.get(f_level, logging.CRITICAL)
            if level_num >= f_level:
                msg = self._build_message(message, f, level, msg_num)
                logging.getLogger(f).log(level_num, msg, **kwargs)

    def _build_message(self, message, destination, level, msg_num):
        pattern = self.__log_patterns[destination]
        tmp = pattern

        tmp = self._format_time(tmp)

        matches = re.findall("(%-?[0]?[0-9]?[AcmNnpPrtT])", tmp)
        for m in matches:
            if "A" in m:
                tmp = self._format_field(tmp, m, ovs.util.PROGRAM_NAME)
            elif "c" in m:
                tmp = self._format_field(tmp, m, self.name)
            elif "m" in m:
                tmp = self._format_field(tmp, m, message)
            elif "N" in m:
                tmp = self._format_field(tmp, m, str(msg_num))
            elif "n" in m:
                tmp = re.sub(m, "\n", tmp)
            elif "p" in m:
                tmp = self._format_field(tmp, m, level.upper())
            elif "P" in m:
                self._format_field(tmp, m, str(os.getpid()))
            elif "r" in m:
                now = datetime.datetime.utcnow()
                delta = now - self.__start_time
                ms = delta.microseconds / 1000
                tmp = self._format_field(tmp, m, str(ms))
            elif "t" in m:
                subprogram = threading.currentThread().getName()
                if subprogram == "MainThread":
                    subprogram = "main"
                tmp = self._format_field(tmp, m, subprogram)
            elif "T" in m:
                subprogram = threading.currentThread().getName()
                if not subprogram == "MainThread":
                    subprogram = "({})".format(subprogram)
                else:
                    subprogram = ""
                tmp = self._format_field(tmp, m, subprogram)
        return tmp.strip()

    def _format_field(self, tmp, match, replace):
        formatting = re.compile("^%(0)?([1-9])?")
        matches = formatting.match(match)
        # Do we need to apply padding?
        if not matches.group(1) and replace != "":
            replace = replace.center(len(replace)+2)
        # Does the field have a minimum width
        if matches.group(2):
            min_width = int(matches.group(2))
            if len(replace) < min_width:
                replace = replace.center(min_width)
        return re.sub(match, replace, tmp)

    def _format_time(self, tmp):
        date_regex = re.compile('(%(0?[1-9]?[dD])(\{(.*)\})?)')
        match = date_regex.search(tmp)

        if match is None:
            return tmp

        # UTC date or Local TZ?
        if match.group(2) == "d":
            now = datetime.datetime.now()
        elif match.group(2) == "D":
            now = datetime.datetime.utcnow()

        # Custom format or ISO format?
        if match.group(3):
            time = datetime.date.strftime(now, match.group(4))
            try:
                i = len(re.search("#+", match.group(4)).group(0))
                msec = '{0:0>{i}.{i}}'.format(str(now.microsecond / 1000), i=i)
                time = re.sub('#+', msec, time)
            except AttributeError:
                pass
        else:
            time = datetime.datetime.isoformat(now.replace(microsecond=0))

        return self._format_field(tmp, match.group(1), time)

    def emer(self, message, **kwargs):
        self.__log("EMER", message, **kwargs)

    def err(self, message, **kwargs):
        self.__log("ERR", message, **kwargs)

    def warn(self, message, **kwargs):
        self.__log("WARN", message, **kwargs)

    def info(self, message, **kwargs):
        self.__log("INFO", message, **kwargs)

    def dbg(self, message, **kwargs):
        self.__log("DBG", message, **kwargs)

    def __is_enabled(self, level):
        level = LEVELS.get(level.lower(), logging.DEBUG)
        for f, f_level in Vlog.__mfl[self.name].iteritems():
            f_level = LEVELS.get(f_level, logging.CRITICAL)
            if level >= f_level:
                return True
        return False

    def emer_is_enabled(self):
        return self.__is_enabled("EMER")

    def err_is_enabled(self):
        return self.__is_enabled("ERR")

    def warn_is_enabled(self):
        return self.__is_enabled("WARN")

    def info_is_enabled(self):
        return self.__is_enabled("INFO")

    def dbg_is_enabled(self):
        return self.__is_enabled("DBG")

    def exception(self, message):
        """Logs 'message' at ERR log level.  Includes a backtrace when in
        exception context."""
        self.err(message, exc_info=True)

    @staticmethod
    def init(log_file=None):
        """Intializes the Vlog module.  Causes Vlog to write to 'log_file' if
        not None.  Should be called after all Vlog objects have been created.
        No logging will occur until this function is called."""

        if Vlog.__inited:
            return

        Vlog.__inited = True
        Vlog.__start_time = datetime.datetime.utcnow()
        logging.raiseExceptions = False
        Vlog.__log_file = log_file
        for f in DESTINATIONS:
            logger = logging.getLogger(f)
            logger.setLevel(logging.DEBUG)

            try:
                if f == "console":
                    logger.addHandler(logging.StreamHandler(sys.stderr))
                elif f == "syslog":
                    Vlog.add_syslog_handler()
                elif f == "file" and Vlog.__log_file:
                    Vlog.__file_handler = logging.FileHandler(Vlog.__log_file)
                    logger.addHandler(Vlog.__file_handler)
            except (IOError, socket.error):
                logger.setLevel(logging.CRITICAL)

        ovs.unixctl.command_register("vlog/reopen", "", 0, 0,
                                     Vlog._unixctl_vlog_reopen, None)
        ovs.unixctl.command_register("vlog/set", "spec", 1, sys.maxint,
                                     Vlog._unixctl_vlog_set, None)
        ovs.unixctl.command_register("vlog/list", "", 0, 0,
                                     Vlog._unixctl_vlog_list, None)

    @staticmethod
    def set_level(module, destination, level):
        """ Sets the log level of the 'module'-'destination' tuple to 'level'.
        All three arguments are strings which are interpreted the same as
        arguments to the --verbose flag.  Should be called after all Vlog
        objects have already been created."""

        module = module.lower()
        destination = destination.lower()
        level = level.lower()

        if destination != "any" and destination not in DESTINATIONS:
            return

        if module != "any" and module not in Vlog.__mfl:
            return

        if level not in LEVELS:
            return

        if module == "any":
            modules = Vlog.__mfl.keys()
        else:
            modules = [module]

        if destination == "any":
            destinations = DESTINATIONS.keys()
        else:
            destinations = [destination]

        for m in modules:
            for f in destinations:
                Vlog.__mfl[m][f] = level

    @staticmethod
    def set_pattern(destination, pattern):
        """ Sets the log pattern of the 'destination' to 'pattern' """
        destination = destination.lower()
        Vlog.__log_patterns[destination] = pattern

    @staticmethod
    def add_syslog_handler(facility=None):
        global syslog_facility, syslog_handler

        # If handler is already added and there is no change in 'facility',
        # there is nothing to do.
        if (not facility or facility == syslog_facility) and syslog_handler:
            return

        logger = logging.getLogger('syslog')
        # If there is no infrastructure to support python syslog, increase
        # the logging severity level to avoid repeated errors.
        if not os.path.exists("/dev/log"):
            logger.setLevel(logging.CRITICAL)
            return

        if syslog_handler:
            logger.removeHandler(syslog_handler)

        if facility:
            syslog_facility = facility

        syslog_handler = logging.handlers.SysLogHandler(address="/dev/log",
                                                    facility=syslog_facility)
        logger.addHandler(syslog_handler)
        return

    @staticmethod
    def set_levels_from_string(s):
        module = None
        level = None
        destination = None

        words = re.split('[ :]', s)
        if words[0] == "pattern":
            try:
                if words[1] in DESTINATIONS and words[2]:
                    segments = [words[i] for i in range(2, len(words))]
                    pattern = "".join(segments)
                    Vlog.set_pattern(words[1], pattern)
                    return
                else:
                    return "Destination %s does not exist" % words[1]
            except IndexError:
                return "Please supply a valid pattern and destination"
        elif words[0] == "FACILITY":
            if words[1] in FACILITIES:
                Vlog.add_syslog_handler(words[1])
                return
            else:
                return "Facility %s is invalid" % words[1]

        for word in [w.lower() for w in words]:
            if word == "any":
                pass
            elif word in DESTINATIONS:
                if destination:
                    return "cannot specify multiple destinations"
                destination = word
            elif word in LEVELS:
                if level:
                    return "cannot specify multiple levels"
                level = word
            elif word in Vlog.__mfl:
                if module:
                    return "cannot specify multiple modules"
                module = word
            else:
                return "no destination, level, or module \"%s\"" % word

        Vlog.set_level(module or "any", destination or "any", level or "any")

    @staticmethod
    def get_levels():
        lines = ["                 console    syslog    file\n",
                 "                 -------    ------    ------\n"]
        lines.extend(sorted(["%-16s  %4s       %4s       %4s\n"
                             % (m,
                                Vlog.__mfl[m]["console"],
                                Vlog.__mfl[m]["syslog"],
                                Vlog.__mfl[m]["file"]) for m in Vlog.__mfl]))
        return ''.join(lines)

    @staticmethod
    def reopen_log_file():
        """Closes and then attempts to re-open the current log file.  (This is
        useful just after log rotation, to ensure that the new log file starts
        being used.)"""

        if Vlog.__log_file:
            logger = logging.getLogger("file")
            logger.removeHandler(Vlog.__file_handler)
            Vlog.__file_handler = logging.FileHandler(Vlog.__log_file)
            logger.addHandler(Vlog.__file_handler)

    @staticmethod
    def _unixctl_vlog_reopen(conn, unused_argv, unused_aux):
        if Vlog.__log_file:
            Vlog.reopen_log_file()
            conn.reply(None)
        else:
            conn.reply("Logging to file not configured")

    @staticmethod
    def _unixctl_vlog_set(conn, argv, unused_aux):
        for arg in argv:
            msg = Vlog.set_levels_from_string(arg)
            if msg:
                conn.reply(msg)
                return
        conn.reply(None)

    @staticmethod
    def _unixctl_vlog_list(conn, unused_argv, unused_aux):
        conn.reply(Vlog.get_levels())


def add_args(parser):
    """Adds vlog related options to 'parser', an ArgumentParser object.  The
    resulting arguments parsed by 'parser' should be passed to handle_args."""

    group = parser.add_argument_group(title="Logging Options")
    group.add_argument("--log-file", nargs="?", const="default",
                       help="Enables logging to a file.  Default log file"
                       " is used if LOG_FILE is omitted.")
    group.add_argument("-v", "--verbose", nargs="*",
                       help="Sets logging levels, see ovs-vswitchd(8)."
                       "  Defaults to dbg.")


def handle_args(args):
    """ Handles command line arguments ('args') parsed by an ArgumentParser.
    The ArgumentParser should have been primed by add_args().  Also takes care
    of initializing the Vlog module."""

    log_file = args.log_file
    if log_file == "default":
        log_file = "%s/%s.log" % (ovs.dirs.LOGDIR, ovs.util.PROGRAM_NAME)

    if args.verbose is None:
        args.verbose = []
    elif args.verbose == []:
        args.verbose = ["any:any:dbg"]

    for verbose in args.verbose:
        msg = Vlog.set_levels_from_string(verbose)
        if msg:
            ovs.util.ovs_fatal(0, "processing \"%s\": %s" % (verbose, msg))

    Vlog.init(log_file)