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 16import datetime 17import logging 18import logging.handlers 19import os 20import re 21import socket 22import sys 23import threading 24 25import ovs.dirs 26import ovs.unixctl 27import ovs.util 28 29import six 30from six.moves import range 31 32DESTINATIONS = {"console": "info", "file": "info", "syslog": "info"} 33PATTERNS = { 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} 38LEVELS = { 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} 46FACILITIES = ['auth', 'authpriv', 'cron', 'daemon', 'ftp', 'kern', 'lpr', 47 'mail', 'news', 'syslog', 'user', 'uucp', 'local0', 'local1', 48 'local2', 'local3', 'local4', 'local5', 'local6', 'local7'] 49syslog_facility = "daemon" 50syslog_handler = '' 51 52 53def get_level(level_str): 54 return LEVELS.get(level_str.lower()) 55 56 57class 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 try: 247 # Windows limitation on Python 2, sys.maxsize is a long number 248 # on 64 bits environments, while sys.maxint is the maximum int 249 # number. Python 3 works as expected. 250 maxsize_int = sys.maxint 251 except AttributeError: 252 maxsize_int = sys.maxsize 253 ovs.unixctl.command_register("vlog/set", "spec", 1, maxsize_int, 254 Vlog._unixctl_vlog_set, None) 255 ovs.unixctl.command_register("vlog/list", "", 0, 0, 256 Vlog._unixctl_vlog_list, None) 257 258 @staticmethod 259 def set_level(module, destination, level): 260 """ Sets the log level of the 'module'-'destination' tuple to 'level'. 261 All three arguments are strings which are interpreted the same as 262 arguments to the --verbose flag. Should be called after all Vlog 263 objects have already been created.""" 264 265 module = module.lower() 266 destination = destination.lower() 267 level = level.lower() 268 269 if destination != "any" and destination not in DESTINATIONS: 270 return 271 272 if module != "any" and module not in Vlog.__mfl: 273 return 274 275 if level not in LEVELS: 276 return 277 278 if module == "any": 279 modules = list(Vlog.__mfl.keys()) 280 else: 281 modules = [module] 282 283 if destination == "any": 284 destinations = list(DESTINATIONS.keys()) 285 else: 286 destinations = [destination] 287 288 for m in modules: 289 for f in destinations: 290 Vlog.__mfl[m][f] = level 291 292 @staticmethod 293 def set_pattern(destination, pattern): 294 """ Sets the log pattern of the 'destination' to 'pattern' """ 295 destination = destination.lower() 296 Vlog.__log_patterns[destination] = pattern 297 298 @staticmethod 299 def add_syslog_handler(facility=None): 300 global syslog_facility, syslog_handler 301 302 # If handler is already added and there is no change in 'facility', 303 # there is nothing to do. 304 if (not facility or facility == syslog_facility) and syslog_handler: 305 return 306 307 logger = logging.getLogger('syslog') 308 # If there is no infrastructure to support python syslog, disable 309 # the logger to avoid repeated errors. 310 if not os.path.exists("/dev/log"): 311 logger.disabled = True 312 return 313 314 if syslog_handler: 315 logger.removeHandler(syslog_handler) 316 317 if facility: 318 syslog_facility = facility 319 320 syslog_handler = logging.handlers.SysLogHandler(address="/dev/log", 321 facility=syslog_facility) 322 logger.addHandler(syslog_handler) 323 return 324 325 @staticmethod 326 def set_levels_from_string(s): 327 module = None 328 level = None 329 destination = None 330 331 words = re.split('[ :]', s) 332 if words[0] == "pattern": 333 try: 334 if words[1] in DESTINATIONS and words[2]: 335 segments = [words[i] for i in range(2, len(words))] 336 pattern = "".join(segments) 337 Vlog.set_pattern(words[1], pattern) 338 return 339 else: 340 return "Destination %s does not exist" % words[1] 341 except IndexError: 342 return "Please supply a valid pattern and destination" 343 elif words[0] == "FACILITY": 344 if words[1] in FACILITIES: 345 Vlog.add_syslog_handler(words[1]) 346 return 347 else: 348 return "Facility %s is invalid" % words[1] 349 350 for word in [w.lower() for w in words]: 351 if word == "any": 352 pass 353 elif word in DESTINATIONS: 354 if destination: 355 return "cannot specify multiple destinations" 356 destination = word 357 elif word in LEVELS: 358 if level: 359 return "cannot specify multiple levels" 360 level = word 361 elif word in Vlog.__mfl: 362 if module: 363 return "cannot specify multiple modules" 364 module = word 365 else: 366 return "no destination, level, or module \"%s\"" % word 367 368 Vlog.set_level(module or "any", destination or "any", level or "any") 369 370 @staticmethod 371 def get_levels(): 372 lines = [" console syslog file\n", 373 " ------- ------ ------\n"] 374 lines.extend(sorted(["%-16s %4s %4s %4s\n" 375 % (m, 376 Vlog.__mfl[m]["console"], 377 Vlog.__mfl[m]["syslog"], 378 Vlog.__mfl[m]["file"]) for m in Vlog.__mfl])) 379 return ''.join(lines) 380 381 @staticmethod 382 def reopen_log_file(): 383 """Closes and then attempts to re-open the current log file. (This is 384 useful just after log rotation, to ensure that the new log file starts 385 being used.)""" 386 387 if Vlog.__log_file: 388 logger = logging.getLogger("file") 389 logger.removeHandler(Vlog.__file_handler) 390 Vlog.__file_handler = logging.FileHandler(Vlog.__log_file) 391 logger.addHandler(Vlog.__file_handler) 392 393 @staticmethod 394 def close_log_file(): 395 """Closes the current log file. (This is useful on Windows, to ensure 396 that a reference to the file is not kept by the daemon in case of 397 detach.)""" 398 if Vlog.__log_file: 399 logger = logging.getLogger("file") 400 logger.removeHandler(Vlog.__file_handler) 401 Vlog.__file_handler.close() 402 403 @staticmethod 404 def _unixctl_vlog_reopen(conn, unused_argv, unused_aux): 405 if Vlog.__log_file: 406 Vlog.reopen_log_file() 407 conn.reply(None) 408 else: 409 conn.reply("Logging to file not configured") 410 411 @staticmethod 412 def _unixctl_vlog_close(conn, unused_argv, unused_aux): 413 if Vlog.__log_file: 414 if sys.platform != 'win32': 415 logger = logging.getLogger("file") 416 logger.removeHandler(Vlog.__file_handler) 417 else: 418 Vlog.close_log_file() 419 conn.reply(None) 420 421 @staticmethod 422 def _unixctl_vlog_set(conn, argv, unused_aux): 423 for arg in argv: 424 msg = Vlog.set_levels_from_string(arg) 425 if msg: 426 conn.reply(msg) 427 return 428 conn.reply(None) 429 430 @staticmethod 431 def _unixctl_vlog_list(conn, unused_argv, unused_aux): 432 conn.reply(Vlog.get_levels()) 433 434 435def add_args(parser): 436 """Adds vlog related options to 'parser', an ArgumentParser object. The 437 resulting arguments parsed by 'parser' should be passed to handle_args.""" 438 439 group = parser.add_argument_group(title="Logging Options") 440 group.add_argument("--log-file", nargs="?", const="default", 441 help="Enables logging to a file. Default log file" 442 " is used if LOG_FILE is omitted.") 443 group.add_argument("-v", "--verbose", nargs="*", 444 help="Sets logging levels, see ovs-vswitchd(8)." 445 " Defaults to dbg.") 446 447 448def handle_args(args): 449 """ Handles command line arguments ('args') parsed by an ArgumentParser. 450 The ArgumentParser should have been primed by add_args(). Also takes care 451 of initializing the Vlog module.""" 452 453 log_file = args.log_file 454 if log_file == "default": 455 log_file = "%s/%s.log" % (ovs.dirs.LOGDIR, ovs.util.PROGRAM_NAME) 456 457 if args.verbose is None: 458 args.verbose = [] 459 elif args.verbose == []: 460 args.verbose = ["any:any:dbg"] 461 462 for verbose in args.verbose: 463 msg = Vlog.set_levels_from_string(verbose) 464 if msg: 465 ovs.util.ovs_fatal(0, "processing \"%s\": %s" % (verbose, msg)) 466 467 Vlog.init(log_file) 468