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 six
from six.moves import range

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(object):
    __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 six.iteritems(Vlog.__mfl[self.name]):
            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 six.iteritems(Vlog.__mfl[self.name]):
            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 = list(Vlog.__mfl.keys())
        else:
            modules = [module]

        if destination == "any":
            destinations = list(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)