# Copyright (c) 2011, 2012, 2013, 2015, 2016 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(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 Vlog.__mfl[self.name].items(): 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.replace('\\', r'\\'), tmp) def _format_time(self, tmp): date_regex = re.compile(r'(%(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].items(): 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.disabled = True ovs.unixctl.command_register("vlog/reopen", "", 0, 0, Vlog._unixctl_vlog_reopen, None) ovs.unixctl.command_register("vlog/close", "", 0, 0, Vlog._unixctl_vlog_close, None) try: # Windows limitation on Python 2, sys.maxsize is a long number # on 64 bits environments, while sys.maxint is the maximum int # number. Python 3 works as expected. maxsize_int = sys.maxint except AttributeError: maxsize_int = sys.maxsize ovs.unixctl.command_register("vlog/set", "spec", 1, maxsize_int, 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') # Disable the logger if the "null" syslog method requested # by environment. if os.environ.get('OVS_SYSLOG_METHOD') == "null": logger.disabled = True return if facility is None: facility = syslog_facility new_handler = logging.handlers.SysLogHandler(address="/dev/log", facility=facility) if syslog_handler: logger.removeHandler(syslog_handler) syslog_handler = new_handler syslog_facility = 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: try: Vlog.add_syslog_handler(words[1]) except (IOError, socket.error): logger = logging.getLogger('syslog') logger.disabled = True 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 close_log_file(): """Closes the current log file. (This is useful on Windows, to ensure that a reference to the file is not kept by the daemon in case of detach.)""" if Vlog.__log_file: logger = logging.getLogger("file") logger.removeHandler(Vlog.__file_handler) Vlog.__file_handler.close() @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_close(conn, unused_argv, unused_aux): if Vlog.__log_file: if sys.platform != 'win32': logger = logging.getLogger("file") logger.removeHandler(Vlog.__file_handler) else: Vlog.close_log_file() conn.reply(None) @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)