python/ovs/vlog.py

   1
   2 # Copyright (c) 2011, 2012, 2013 Nicira, Inc.
   3 #
   4 # Licensed under the Apache License, Version 2.0 (the "License");
   5 # you may not use this file except in compliance with the License.
   6 # You may obtain a copy of the License at:
   7 #
   8 #     http://www.apache.org/licenses/LICENSE-2.0
   9 #
  10 # Unless required by applicable law or agreed to in writing, software
  11 # distributed under the License is distributed on an "AS IS" BASIS,
  12 # WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
  13 # See the License for the specific language governing permissions and
  14 # limitations under the License.
  15
  16 import datetime
  17 import logging
  18 import logging.handlers
  19 import os
  20 import re
  21 import socket
  22 import sys
  23 import threading
  24
  25 import ovs.dirs
  26 import ovs.unixctl
  27 import ovs.util
  28
  29 FACILITIES = {"console": "info", "file": "info", "syslog": "info"}
  30 PATTERNS = {
  31     "console": "%D{%Y-%m-%dT%H:%M:%SZ}|%05N|%c%T|%p|%m",
  32     "file": "%D{%Y-%m-%dT%H:%M:%S.###Z}|%05N|%c%T|%p|%m",
  33     "syslog": "ovs|%05N|%c%T|%p|%m",
  34 }
  35 LEVELS = {
  36     "dbg": logging.DEBUG,
  37     "info": logging.INFO,
  38     "warn": logging.WARNING,
  39     "err": logging.ERROR,
  40     "emer": logging.CRITICAL,
  41     "off": logging.CRITICAL
  42 }
  43
  44
  45 def get_level(level_str):
  46     return LEVELS.get(level_str.lower())
  47
  48
  49 class Vlog:
  50     __inited = False
  51     __msg_num = 0
  52     __start_time = 0
  53     __mfl = {}  # Module -> facility -> level
  54     __log_file = None
  55     __file_handler = None
  56     __log_patterns = PATTERNS
  57
  58     def __init__(self, name):
  59         """Creates a new Vlog object representing a module called 'name'.  The
  60         created Vlog object will do nothing until the Vlog.init() static method
  61         is called.  Once called, no more Vlog objects may be created."""
  62
  63         assert not Vlog.__inited
  64         self.name = name.lower()
  65         if name not in Vlog.__mfl:
  66             Vlog.__mfl[self.name] = FACILITIES.copy()
  67
  68     def __log(self, level, message, **kwargs):
  69         if not Vlog.__inited:
  70             return
  71
  72         level_num = LEVELS.get(level.lower(), logging.DEBUG)
  73         msg_num = Vlog.__msg_num
  74         Vlog.__msg_num += 1
  75
  76         for f, f_level in Vlog.__mfl[self.name].iteritems():
  77             f_level = LEVELS.get(f_level, logging.CRITICAL)
  78             if level_num >= f_level:
  79                 msg = self._build_message(message, f, level, msg_num)
  80                 logging.getLogger(f).log(level_num, msg, **kwargs)
  81
  82     def _build_message(self, message, facility, level, msg_num):
  83         pattern = self.__log_patterns[facility]
  84         tmp = pattern
  85
  86         tmp = self._format_time(tmp)
  87
  88         matches = re.findall("(%-?[0]?[0-9]?[AcmNnpPrtT])", tmp)
  89         for m in matches:
  90             if "A" in m:
  91                 tmp = self._format_field(tmp, m, ovs.util.PROGRAM_NAME)
  92             elif "c" in m:
  93                 tmp = self._format_field(tmp, m, self.name)
  94             elif "m" in m:
  95                 tmp = self._format_field(tmp, m, message)
  96             elif "N" in m:
  97                 tmp = self._format_field(tmp, m, str(msg_num))
  98             elif "n" in m:
  99                 tmp = re.sub(m, "\n", tmp)
 100             elif "p" in m:
 101                 tmp = self._format_field(tmp, m, level.upper())
 102             elif "P" in m:
 103                 self._format_field(tmp, m, str(os.getpid()))
 104             elif "r" in m:
 105                 now = datetime.datetime.utcnow()
 106                 delta = now - self.__start_time
 107                 ms = delta.microseconds / 1000
 108                 tmp = self._format_field(tmp, m, str(ms))
 109             elif "t" in m:
 110                 subprogram = threading.current_thread().name
 111                 if subprogram == "MainThread":
 112                     subprogram = "main"
 113                 tmp = self._format_field(tmp, m, subprogram)
 114             elif "T" in m:
 115                 subprogram = threading.current_thread().name
 116                 if not subprogram == "MainThread":
 117                     subprogram = "({})".format(subprogram)
 118                 else:
 119                     subprogram = ""
 120                 tmp = self._format_field(tmp, m, subprogram)
 121         return tmp.strip()
 122
 123     def _format_field(self, tmp, match, replace):
 124         formatting = re.compile("^%(0)?([1-9])?")
 125         matches = formatting.match(match)
 126         # Do we need to apply padding?
 127         if not matches.group(1) and replace != "":
 128             replace = replace.center(len(replace)+2)
 129         # Does the field have a minimum width
 130         if matches.group(2):
 131             min_width = int(matches.group(2))
 132             if len(replace) < min_width:
 133                 replace = replace.center(min_width)
 134         return re.sub(match, replace, tmp)
 135
 136     def _format_time(self, tmp):
 137         date_regex = re.compile('(%(0?[1-9]?[dD])(\{(.*)\})?)')
 138         match = date_regex.search(tmp)
 139
 140         if match is None:
 141             return tmp
 142
 143         # UTC date or Local TZ?
 144         if match.group(2) == "d":
 145             now = datetime.datetime.now()
 146         elif match.group(2) == "D":
 147             now = datetime.datetime.utcnow()
 148
 149         # Custom format or ISO format?
 150         if match.group(3):
 151             time = datetime.date.strftime(now, match.group(4))
 152             try:
 153                 i = len(re.search("#+", match.group(4)).group(0))
 154                 msec = '{0:0>{i}.{i}}'.format(str(now.microsecond / 1000), i=i)
 155                 time = re.sub('#+', msec, time)
 156             except AttributeError:
 157                 pass
 158         else:
 159             time = datetime.datetime.isoformat(now.replace(microsecond=0))
 160
 161         return self._format_field(tmp, match.group(1), time)
 162
 163     def emer(self, message, **kwargs):
 164         self.__log("EMER", message, **kwargs)
 165
 166     def err(self, message, **kwargs):
 167         self.__log("ERR", message, **kwargs)
 168
 169     def warn(self, message, **kwargs):
 170         self.__log("WARN", message, **kwargs)
 171
 172     def info(self, message, **kwargs):
 173         self.__log("INFO", message, **kwargs)
 174
 175     def dbg(self, message, **kwargs):
 176         self.__log("DBG", message, **kwargs)
 177
 178     def __is_enabled(self, level):
 179         level = LEVELS.get(level.lower(), logging.DEBUG)
 180         for f, f_level in Vlog.__mfl[self.name].iteritems():
 181             f_level = LEVELS.get(f_level, logging.CRITICAL)
 182             if level >= f_level:
 183                 return True
 184         return False
 185
 186     def emer_is_enabled(self):
 187         return self.__is_enabled("EMER")
 188
 189     def err_is_enabled(self):
 190         return self.__is_enabled("ERR")
 191
 192     def warn_is_enabled(self):
 193         return self.__is_enabled("WARN")
 194
 195     def info_is_enabled(self):
 196         return self.__is_enabled("INFO")
 197
 198     def dbg_is_enabled(self):
 199         return self.__is_enabled("DBG")
 200
 201     def exception(self, message):
 202         """Logs 'message' at ERR log level.  Includes a backtrace when in
 203         exception context."""
 204         self.err(message, exc_info=True)
 205
 206     @staticmethod
 207     def init(log_file=None):
 208         """Intializes the Vlog module.  Causes Vlog to write to 'log_file' if
 209         not None.  Should be called after all Vlog objects have been created.
 210         No logging will occur until this function is called."""
 211
 212         if Vlog.__inited:
 213             return
 214
 215         Vlog.__inited = True
 216         Vlog.__start_time = datetime.datetime.utcnow()
 217         logging.raiseExceptions = False
 218         Vlog.__log_file = log_file
 219         for f in FACILITIES:
 220             logger = logging.getLogger(f)
 221             logger.setLevel(logging.DEBUG)
 222
 223             try:
 224                 if f == "console":
 225                     logger.addHandler(logging.StreamHandler(sys.stderr))
 226                 elif f == "syslog":
 227                     logger.addHandler(logging.handlers.SysLogHandler(
 228                         address="/dev/log",
 229                         facility=logging.handlers.SysLogHandler.LOG_DAEMON))
 230                 elif f == "file" and Vlog.__log_file:
 231                     Vlog.__file_handler = logging.FileHandler(Vlog.__log_file)
 232                     logger.addHandler(Vlog.__file_handler)
 233             except (IOError, socket.error):
 234                 logger.setLevel(logging.CRITICAL)
 235
 236         ovs.unixctl.command_register("vlog/reopen", "", 0, 0,
 237                                      Vlog._unixctl_vlog_reopen, None)
 238         ovs.unixctl.command_register("vlog/set", "spec", 1, sys.maxint,
 239                                      Vlog._unixctl_vlog_set, None)
 240         ovs.unixctl.command_register("vlog/list", "", 0, 0,
 241                                      Vlog._unixctl_vlog_list, None)
 242
 243     @staticmethod
 244     def set_level(module, facility, level):
 245         """ Sets the log level of the 'module'-'facility' tuple to 'level'.
 246         All three arguments are strings which are interpreted the same as
 247         arguments to the --verbose flag.  Should be called after all Vlog
 248         objects have already been created."""
 249
 250         module = module.lower()
 251         facility = facility.lower()
 252         level = level.lower()
 253
 254         if facility != "any" and facility not in FACILITIES:
 255             return
 256
 257         if module != "any" and module not in Vlog.__mfl:
 258             return
 259
 260         if level not in LEVELS:
 261             return
 262
 263         if module == "any":
 264             modules = Vlog.__mfl.keys()
 265         else:
 266             modules = [module]
 267
 268         if facility == "any":
 269             facilities = FACILITIES.keys()
 270         else:
 271             facilities = [facility]
 272
 273         for m in modules:
 274             for f in facilities:
 275                 Vlog.__mfl[m][f] = level
 276
 277     @staticmethod
 278     def set_pattern(facility, pattern):
 279         """ Sets the log pattern of the 'facility' to 'pattern' """
 280         facility = facility.lower()
 281         Vlog.__log_patterns[facility] = pattern
 282
 283     @staticmethod
 284     def set_levels_from_string(s):
 285         module = None
 286         level = None
 287         facility = None
 288
 289         words = re.split('[ :]', s)
 290         if words[0] == "pattern":
 291             try:
 292                 if words[1] in FACILITIES and words[2]:
 293                     segments = [words[i] for i in range(2, len(words))]
 294                     pattern = "".join(segments)
 295                     Vlog.set_pattern(words[1], pattern)
 296                     return
 297                 else:
 298                     return "Facility %s does not exist" % words[1]
 299             except IndexError:
 300                 return "Please supply a valid pattern and facility"
 301
 302         for word in [w.lower() for w in words]:
 303             if word == "any":
 304                 pass
 305             elif word in FACILITIES:
 306                 if facility:
 307                     return "cannot specify multiple facilities"
 308                 facility = word
 309             elif word in LEVELS:
 310                 if level:
 311                     return "cannot specify multiple levels"
 312                 level = word
 313             elif word in Vlog.__mfl:
 314                 if module:
 315                     return "cannot specify multiple modules"
 316                 module = word
 317             else:
 318                 return "no facility, level, or module \"%s\"" % word
 319
 320         Vlog.set_level(module or "any", facility or "any", level or "any")
 321
 322     @staticmethod
 323     def get_levels():
 324         lines = ["                 console    syslog    file\n",
 325                  "                 -------    ------    ------\n"]
 326         lines.extend(sorted(["%-16s  %4s       %4s       %4s\n"
 327                              % (m,
 328                                 Vlog.__mfl[m]["console"],
 329                                 Vlog.__mfl[m]["syslog"],
 330                                 Vlog.__mfl[m]["file"]) for m in Vlog.__mfl]))
 331         return ''.join(lines)
 332
 333     @staticmethod
 334     def reopen_log_file():
 335         """Closes and then attempts to re-open the current log file.  (This is
 336         useful just after log rotation, to ensure that the new log file starts
 337         being used.)"""
 338
 339         if Vlog.__log_file:
 340             logger = logging.getLogger("file")
 341             logger.removeHandler(Vlog.__file_handler)
 342             Vlog.__file_handler = logging.FileHandler(Vlog.__log_file)
 343             logger.addHandler(Vlog.__file_handler)
 344
 345     @staticmethod
 346     def _unixctl_vlog_reopen(conn, unused_argv, unused_aux):
 347         if Vlog.__log_file:
 348             Vlog.reopen_log_file()
 349             conn.reply(None)
 350         else:
 351             conn.reply("Logging to file not configured")
 352
 353     @staticmethod
 354     def _unixctl_vlog_set(conn, argv, unused_aux):
 355         for arg in argv:
 356             msg = Vlog.set_levels_from_string(arg)
 357             if msg:
 358                 conn.reply(msg)
 359                 return
 360         conn.reply(None)
 361
 362     @staticmethod
 363     def _unixctl_vlog_list(conn, unused_argv, unused_aux):
 364         conn.reply(Vlog.get_levels())
 365
 366
 367 def add_args(parser):
 368     """Adds vlog related options to 'parser', an ArgumentParser object.  The
 369     resulting arguments parsed by 'parser' should be passed to handle_args."""
 370
 371     group = parser.add_argument_group(title="Logging Options")
 372     group.add_argument("--log-file", nargs="?", const="default",
 373                        help="Enables logging to a file.  Default log file"
 374                        " is used if LOG_FILE is omitted.")
 375     group.add_argument("-v", "--verbose", nargs="*",
 376                        help="Sets logging levels, see ovs-vswitchd(8)."
 377                        "  Defaults to dbg.")
 378
 379
 380 def handle_args(args):
 381     """ Handles command line arguments ('args') parsed by an ArgumentParser.
 382     The ArgumentParser should have been primed by add_args().  Also takes care
 383     of initializing the Vlog module."""
 384
 385     log_file = args.log_file
 386     if log_file == "default":
 387         log_file = "%s/%s.log" % (ovs.dirs.LOGDIR, ovs.util.PROGRAM_NAME)
 388
 389     if args.verbose is None:
 390         args.verbose = []
 391     elif args.verbose == []:
 392         args.verbose = ["any:any:dbg"]
 393
 394     for verbose in args.verbose:
 395         msg = Vlog.set_levels_from_string(verbose)
 396         if msg:
 397             ovs.util.ovs_fatal(0, "processing \"%s\": %s" % (verbose, msg))
 398
 399     Vlog.init(log_file)