python/ovs/vlog.py

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