Python Logging Formatting Improvements
[sliver-openvswitch.git] / python / ovs / vlog.py
index ad53781..580b1bc 100644 (file)
@@ -1,5 +1,5 @@
 
-# Copyright (c) 2011 Nicira Networks
+# 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.
 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
 
 FACILITIES = {"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,
@@ -40,7 +49,11 @@ def get_level(level_str):
 class Vlog:
     __inited = False
     __msg_num = 0
+    __start_time = 0
     __mfl = {}  # Module -> facility -> 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
@@ -56,17 +69,96 @@ class Vlog:
         if not Vlog.__inited:
             return
 
-        now = datetime.datetime.now().strftime("%b %d %H:%M:%S")
-        message = ("%s|%s|%s|%s|%s"
-                   % (now, Vlog.__msg_num, self.name, level, message))
-
-        level = LEVELS.get(level.lower(), logging.DEBUG)
+        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 >= f_level:
-                logging.getLogger(f).log(level, message, **kwargs)
+            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, facility, level, msg_num):
+        pattern = self.__log_patterns[facility]
+        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.current_thread().name
+                if subprogram == "MainThread":
+                    subprogram = "main"
+                tmp = self._format_field(tmp, m, subprogram)
+            elif "T" in m:
+                subprogram = threading.current_thread().name
+                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)
@@ -83,6 +175,29 @@ class Vlog:
     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."""
@@ -98,7 +213,9 @@ class Vlog:
             return
 
         Vlog.__inited = True
+        Vlog.__start_time = datetime.datetime.utcnow()
         logging.raiseExceptions = False
+        Vlog.__log_file = log_file
         for f in FACILITIES:
             logger = logging.getLogger(f)
             logger.setLevel(logging.DEBUG)
@@ -110,11 +227,19 @@ class Vlog:
                     logger.addHandler(logging.handlers.SysLogHandler(
                         address="/dev/log",
                         facility=logging.handlers.SysLogHandler.LOG_DAEMON))
-                elif f == "file" and log_file:
-                    logger.addHandler(logging.FileHandler(log_file))
+                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, facility, level):
         """ Sets the log level of the 'module'-'facility' tuple to 'level'.
@@ -149,6 +274,95 @@ class Vlog:
             for f in facilities:
                 Vlog.__mfl[m][f] = level
 
+    @staticmethod
+    def set_pattern(facility, pattern):
+        """ Sets the log pattern of the 'facility' to 'pattern' """
+        facility = facility.lower()
+        Vlog.__log_patterns[facility] = pattern
+
+    @staticmethod
+    def set_levels_from_string(s):
+        module = None
+        level = None
+        facility = None
+
+        words = re.split('[ :]', s)
+        if words[0] == "pattern":
+            try:
+                if words[1] in FACILITIES 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 "Facility %s does not exist" % words[1]
+            except IndexError:
+                return "Please supply a valid pattern and facility"
+
+        for word in [w.lower() for w in words]:
+            if word == "any":
+                pass
+            elif word in FACILITIES:
+                if facility:
+                    return "cannot specify multiple facilities"
+                facility = 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 facility, level, or module \"%s\"" % word
+
+        Vlog.set_level(module or "any", facility 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
@@ -160,7 +374,7 @@ def add_args(parser):
                        " is used if LOG_FILE is omitted.")
     group.add_argument("-v", "--verbose", nargs="*",
                        help="Sets logging levels, see ovs-vswitchd(8)."
-                       "  Defaults to ANY:ANY:dbg.")
+                       "  Defaults to dbg.")
 
 
 def handle_args(args):
@@ -178,23 +392,8 @@ def handle_args(args):
         args.verbose = ["any:any:dbg"]
 
     for verbose in args.verbose:
-        args = verbose.split(':')
-
-        if len(args) >= 3:
-            level = args[2]
-        else:
-            level = "dbg"
-
-        if len(args) >= 2:
-            facility = args[1]
-        else:
-            facility = "any"
-
-        if len(args) >= 1:
-            module = args[0]
-        else:
-            module = "any"
-
-        Vlog.set_level(module, facility, level)
+        msg = Vlog.set_levels_from_string(verbose)
+        if msg:
+            ovs.util.ovs_fatal(0, "processing \"%s\": %s" % (verbose, msg))
 
     Vlog.init(log_file)