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 DESTINATIONS = {"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 FACILITIES = ['auth', 'authpriv', 'cron', 'daemon', 'ftp', 'kern', 'lpr',
  44               'mail', 'news', 'syslog', 'user', 'uucp', 'local0', 'local1',
  45               'local2', 'local3', 'local4', 'local5', 'local6', 'local7']
  46 syslog_facility = "daemon"
  47 syslog_handler = ''
  48
  49
  50 def get_level(level_str):
  51     return LEVELS.get(level_str.lower())
  52
  53
  54 class Vlog:
  55     __inited = False
  56     __msg_num = 0
  57     __start_time = 0
  58     __mfl = {}  # Module -> destination -> level
  59     __log_file = None
  60     __file_handler = None
  61     __log_patterns = PATTERNS
  62
  63     def __init__(self, name):
  64         """Creates a new Vlog object representing a module called 'name'.  The
  65         created Vlog object will do nothing until the Vlog.init() static method
  66         is called.  Once called, no more Vlog objects may be created."""
  67
  68         assert not Vlog.__inited
  69         self.name = name.lower()
  70         if name not in Vlog.__mfl:
  71             Vlog.__mfl[self.name] = DESTINATIONS.copy()
  72
  73     def __log(self, level, message, **kwargs):
  74         if not Vlog.__inited:
  75             return
  76
  77         level_num = LEVELS.get(level.lower(), logging.DEBUG)
  78         msg_num = Vlog.__msg_num
  79         Vlog.__msg_num += 1
  80
  81         for f, f_level in Vlog.__mfl[self.name].iteritems():
  82             f_level = LEVELS.get(f_level, logging.CRITICAL)
  83             if level_num >= f_level:
  84                 msg = self._build_message(message, f, level, msg_num)
  85                 logging.getLogger(f).log(level_num, msg, **kwargs)
  86
  87     def _build_message(self, message, destination, level, msg_num):
  88         pattern = self.__log_patterns[destination]
  89         tmp = pattern
  90
  91         tmp = self._format_time(tmp)
  92
  93         matches = re.findall("(%-?[0]?[0-9]?[AcmNnpPrtT])", tmp)
  94         for m in matches:
  95             if "A" in m:
  96                 tmp = self._format_field(tmp, m, ovs.util.PROGRAM_NAME)
  97             elif "c" in m:
  98                 tmp = self._format_field(tmp, m, self.name)
  99             elif "m" in m:
 100                 tmp = self._format_field(tmp, m, message)
 101             elif "N" in m:
 102                 tmp = self._format_field(tmp, m, str(msg_num))
 103             elif "n" in m:
 104                 tmp = re.sub(m, "\n", tmp)
 105             elif "p" in m:
 106                 tmp = self._format_field(tmp, m, level.upper())
 107             elif "P" in m:
 108                 self._format_field(tmp, m, str(os.getpid()))
 109             elif "r" in m:
 110                 now = datetime.datetime.utcnow()
 111                 delta = now - self.__start_time
 112                 ms = delta.microseconds / 1000
 113                 tmp = self._format_field(tmp, m, str(ms))
 114             elif "t" in m:
 115                 subprogram = threading.currentThread().getName()
 116                 if subprogram == "MainThread":
 117                     subprogram = "main"
 118                 tmp = self._format_field(tmp, m, subprogram)
 119             elif "T" in m:
 120                 subprogram = threading.currentThread().getName()
 121                 if not subprogram == "MainThread":
 122                     subprogram = "({})".format(subprogram)
 123                 else:
 124                     subprogram = ""
 125                 tmp = self._format_field(tmp, m, subprogram)
 126         return tmp.strip()
 127
 128     def _format_field(self, tmp, match, replace):
 129         formatting = re.compile("^%(0)?([1-9])?")
 130         matches = formatting.match(match)
 131         # Do we need to apply padding?
 132         if not matches.group(1) and replace != "":
 133             replace = replace.center(len(replace)+2)
 134         # Does the field have a minimum width
 135         if matches.group(2):
 136             min_width = int(matches.group(2))
 137             if len(replace) < min_width:
 138                 replace = replace.center(min_width)
 139         return re.sub(match, replace, tmp)
 140
 141     def _format_time(self, tmp):
 142         date_regex = re.compile('(%(0?[1-9]?[dD])(\{(.*)\})?)')
 143         match = date_regex.search(tmp)
 144
 145         if match is None:
 146             return tmp
 147
 148         # UTC date or Local TZ?
 149         if match.group(2) == "d":
 150             now = datetime.datetime.now()
 151         elif match.group(2) == "D":
 152             now = datetime.datetime.utcnow()
 153
 154         # Custom format or ISO format?
 155         if match.group(3):
 156             time = datetime.date.strftime(now, match.group(4))
 157             try:
 158                 i = len(re.search("#+", match.group(4)).group(0))
 159                 msec = '{0:0>{i}.{i}}'.format(str(now.microsecond / 1000), i=i)
 160                 time = re.sub('#+', msec, time)
 161             except AttributeError:
 162                 pass
 163         else:
 164             time = datetime.datetime.isoformat(now.replace(microsecond=0))
 165
 166         return self._format_field(tmp, match.group(1), time)
 167
 168     def emer(self, message, **kwargs):
 169         self.__log("EMER", message, **kwargs)
 170
 171     def err(self, message, **kwargs):
 172         self.__log("ERR", message, **kwargs)
 173
 174     def warn(self, message, **kwargs):
 175         self.__log("WARN", message, **kwargs)
 176
 177     def info(self, message, **kwargs):
 178         self.__log("INFO", message, **kwargs)
 179
 180     def dbg(self, message, **kwargs):
 181         self.__log("DBG", message, **kwargs)
 182
 183     def __is_enabled(self, level):
 184         level = LEVELS.get(level.lower(), logging.DEBUG)
 185         for f, f_level in Vlog.__mfl[self.name].iteritems():
 186             f_level = LEVELS.get(f_level, logging.CRITICAL)
 187             if level >= f_level:
 188                 return True
 189         return False
 190
 191     def emer_is_enabled(self):
 192         return self.__is_enabled("EMER")
 193
 194     def err_is_enabled(self):
 195         return self.__is_enabled("ERR")
 196
 197     def warn_is_enabled(self):
 198         return self.__is_enabled("WARN")
 199
 200     def info_is_enabled(self):
 201         return self.__is_enabled("INFO")
 202
 203     def dbg_is_enabled(self):
 204         return self.__is_enabled("DBG")
 205
 206     def exception(self, message):
 207         """Logs 'message' at ERR log level.  Includes a backtrace when in
 208         exception context."""
 209         self.err(message, exc_info=True)
 210
 211     @staticmethod
 212     def init(log_file=None):
 213         """Intializes the Vlog module.  Causes Vlog to write to 'log_file' if
 214         not None.  Should be called after all Vlog objects have been created.
 215         No logging will occur until this function is called."""
 216
 217         if Vlog.__inited:
 218             return
 219
 220         Vlog.__inited = True
 221         Vlog.__start_time = datetime.datetime.utcnow()
 222         logging.raiseExceptions = False
 223         Vlog.__log_file = log_file
 224         for f in DESTINATIONS:
 225             logger = logging.getLogger(f)
 226             logger.setLevel(logging.DEBUG)
 227
 228             try:
 229                 if f == "console":
 230                     logger.addHandler(logging.StreamHandler(sys.stderr))
 231                 elif f == "syslog":
 232                     Vlog.add_syslog_handler()
 233                 elif f == "file" and Vlog.__log_file:
 234                     Vlog.__file_handler = logging.FileHandler(Vlog.__log_file)
 235                     logger.addHandler(Vlog.__file_handler)
 236             except (IOError, socket.error):
 237                 logger.setLevel(logging.CRITICAL)
 238
 239         ovs.unixctl.command_register("vlog/reopen", "", 0, 0,
 240                                      Vlog._unixctl_vlog_reopen, None)
 241         ovs.unixctl.command_register("vlog/set", "spec", 1, sys.maxint,
 242                                      Vlog._unixctl_vlog_set, None)
 243         ovs.unixctl.command_register("vlog/list", "", 0, 0,
 244                                      Vlog._unixctl_vlog_list, None)
 245
 246     @staticmethod
 247     def set_level(module, destination, level):
 248         """ Sets the log level of the 'module'-'destination' tuple to 'level'.
 249         All three arguments are strings which are interpreted the same as
 250         arguments to the --verbose flag.  Should be called after all Vlog
 251         objects have already been created."""
 252
 253         module = module.lower()
 254         destination = destination.lower()
 255         level = level.lower()
 256
 257         if destination != "any" and destination not in DESTINATIONS:
 258             return
 259
 260         if module != "any" and module not in Vlog.__mfl:
 261             return
 262
 263         if level not in LEVELS:
 264             return
 265
 266         if module == "any":
 267             modules = Vlog.__mfl.keys()
 268         else:
 269             modules = [module]
 270
 271         if destination == "any":
 272             destinations = DESTINATIONS.keys()
 273         else:
 274             destinations = [destination]
 275
 276         for m in modules:
 277             for f in destinations:
 278                 Vlog.__mfl[m][f] = level
 279
 280     @staticmethod
 281     def set_pattern(destination, pattern):
 282         """ Sets the log pattern of the 'destination' to 'pattern' """
 283         destination = destination.lower()
 284         Vlog.__log_patterns[destination] = pattern
 285
 286     @staticmethod
 287     def add_syslog_handler(facility=None):
 288         global syslog_facility, syslog_handler
 289
 290         # If handler is already added and there is no change in 'facility',
 291         # there is nothing to do.
 292         if (not facility or facility == syslog_facility) and syslog_handler:
 293             return
 294
 295         logger = logging.getLogger('syslog')
 296         # If there is no infrastructure to support python syslog, increase
 297         # the logging severity level to avoid repeated errors.
 298         if not os.path.exists("/dev/log"):
 299             logger.setLevel(logging.CRITICAL)
 300             return
 301
 302         if syslog_handler:
 303             logger.removeHandler(syslog_handler)
 304
 305         if facility:
 306             syslog_facility = facility
 307
 308         syslog_handler = logging.handlers.SysLogHandler(address="/dev/log",
 309                                                     facility=syslog_facility)
 310         logger.addHandler(syslog_handler)
 311         return
 312
 313     @staticmethod
 314     def set_levels_from_string(s):
 315         module = None
 316         level = None
 317         destination = None
 318
 319         words = re.split('[ :]', s)
 320         if words[0] == "pattern":
 321             try:
 322                 if words[1] in DESTINATIONS and words[2]:
 323                     segments = [words[i] for i in range(2, len(words))]
 324                     pattern = "".join(segments)
 325                     Vlog.set_pattern(words[1], pattern)
 326                     return
 327                 else:
 328                     return "Destination %s does not exist" % words[1]
 329             except IndexError:
 330                 return "Please supply a valid pattern and destination"
 331         elif words[0] == "FACILITY":
 332             if words[1] in FACILITIES:
 333                 Vlog.add_syslog_handler(words[1])
 334                 return
 335             else:
 336                 return "Facility %s is invalid" % words[1]
 337
 338         for word in [w.lower() for w in words]:
 339             if word == "any":
 340                 pass
 341             elif word in DESTINATIONS:
 342                 if destination:
 343                     return "cannot specify multiple destinations"
 344                 destination = word
 345             elif word in LEVELS:
 346                 if level:
 347                     return "cannot specify multiple levels"
 348                 level = word
 349             elif word in Vlog.__mfl:
 350                 if module:
 351                     return "cannot specify multiple modules"
 352                 module = word
 353             else:
 354                 return "no destination, level, or module \"%s\"" % word
 355
 356         Vlog.set_level(module or "any", destination or "any", level or "any")
 357
 358     @staticmethod
 359     def get_levels():
 360         lines = ["                 console    syslog    file\n",
 361                  "                 -------    ------    ------\n"]
 362         lines.extend(sorted(["%-16s  %4s       %4s       %4s\n"
 363                              % (m,
 364                                 Vlog.__mfl[m]["console"],
 365                                 Vlog.__mfl[m]["syslog"],
 366                                 Vlog.__mfl[m]["file"]) for m in Vlog.__mfl]))
 367         return ''.join(lines)
 368
 369     @staticmethod
 370     def reopen_log_file():
 371         """Closes and then attempts to re-open the current log file.  (This is
 372         useful just after log rotation, to ensure that the new log file starts
 373         being used.)"""
 374
 375         if Vlog.__log_file:
 376             logger = logging.getLogger("file")
 377             logger.removeHandler(Vlog.__file_handler)
 378             Vlog.__file_handler = logging.FileHandler(Vlog.__log_file)
 379             logger.addHandler(Vlog.__file_handler)
 380
 381     @staticmethod
 382     def _unixctl_vlog_reopen(conn, unused_argv, unused_aux):
 383         if Vlog.__log_file:
 384             Vlog.reopen_log_file()
 385             conn.reply(None)
 386         else:
 387             conn.reply("Logging to file not configured")
 388
 389     @staticmethod
 390     def _unixctl_vlog_set(conn, argv, unused_aux):
 391         for arg in argv:
 392             msg = Vlog.set_levels_from_string(arg)
 393             if msg:
 394                 conn.reply(msg)
 395                 return
 396         conn.reply(None)
 397
 398     @staticmethod
 399     def _unixctl_vlog_list(conn, unused_argv, unused_aux):
 400         conn.reply(Vlog.get_levels())
 401
 402
 403 def add_args(parser):
 404     """Adds vlog related options to 'parser', an ArgumentParser object.  The
 405     resulting arguments parsed by 'parser' should be passed to handle_args."""
 406
 407     group = parser.add_argument_group(title="Logging Options")
 408     group.add_argument("--log-file", nargs="?", const="default",
 409                        help="Enables logging to a file.  Default log file"
 410                        " is used if LOG_FILE is omitted.")
 411     group.add_argument("-v", "--verbose", nargs="*",
 412                        help="Sets logging levels, see ovs-vswitchd(8)."
 413                        "  Defaults to dbg.")
 414
 415
 416 def handle_args(args):
 417     """ Handles command line arguments ('args') parsed by an ArgumentParser.
 418     The ArgumentParser should have been primed by add_args().  Also takes care
 419     of initializing the Vlog module."""
 420
 421     log_file = args.log_file
 422     if log_file == "default":
 423         log_file = "%s/%s.log" % (ovs.dirs.LOGDIR, ovs.util.PROGRAM_NAME)
 424
 425     if args.verbose is None:
 426         args.verbose = []
 427     elif args.verbose == []:
 428         args.verbose = ["any:any:dbg"]
 429
 430     for verbose in args.verbose:
 431         msg = Vlog.set_levels_from_string(verbose)
 432         if msg:
 433             ovs.util.ovs_fatal(0, "processing \"%s\": %s" % (verbose, msg))
 434
 435     Vlog.init(log_file)