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