Package flumotion :: Package common :: Module log
[hide private]

Source Code for Module flumotion.common.log

  1  # -*- Mode: Python; test-case-name: flumotion.test.test_log -*- 
  2  # vi:si:et:sw=4:sts=4:ts=4 
  3  # 
  4  # Flumotion - a streaming media server 
  5  # Copyright (C) 2004,2005,2006,2007 Fluendo, S.L. (www.fluendo.com). 
  6  # All rights reserved. 
  7   
  8  # This file may be distributed and/or modified under the terms of 
  9  # the GNU General Public License version 2 as published by 
 10  # the Free Software Foundation. 
 11  # This file is distributed without any warranty; without even the implied 
 12  # warranty of merchantability or fitness for a particular purpose. 
 13  # See "LICENSE.GPL" in the source distribution for more information. 
 14   
 15  # Licensees having purchased or holding a valid Flumotion Advanced 
 16  # Streaming Server license may use this file in accordance with the 
 17  # Flumotion Advanced Streaming Server Commercial License Agreement. 
 18  # See "LICENSE.Flumotion" in the source distribution for more information. 
 19   
 20  # Headers in this file shall remain intact. 
 21   
 22  """ 
 23  Flumotion logging 
 24   
 25  Just like in GStreamer, five levels of log information are defined. 
 26  These are, in order of decreasing verbosity: log, debug, info, warning, error. 
 27   
 28  API Stability: stabilizing 
 29   
 30  Maintainer: U{Thomas Vander Stichele <thomas at apestaart dot org>} 
 31  """ 
 32   
 33  import errno 
 34  import sys 
 35  import os 
 36  import fnmatch 
 37  import time 
 38  import types 
 39  import traceback 
 40   
 41  # environment variables controlling levels for each category 
 42  _FLU_DEBUG = "*:1" 
 43   
 44  # dynamic dictionary of categories already seen and their level 
 45  _categories = {} 
 46   
 47  # log handlers registered 
 48  _log_handlers = [] 
 49  _log_handlers_limited = [] 
 50   
 51  _initialized = False 
 52   
 53  # public log levels 
 54  ERROR = 1 
 55  WARN = 2 
 56  INFO = 3 
 57  DEBUG = 4 
 58  LOG = 5 
 59   
60 -def getLevelName(level):
61 """ 62 Return the name of a log level. 63 """ 64 assert isinstance(level, int) and level > 0 and level < 6, \ 65 "Bad debug level" 66 return ('ERROR', 'WARN', 'INFO', 'DEBUG', 'LOG')[level - 1]
67
68 -def registerCategory(category):
69 """ 70 Register a given category in the debug system. 71 A level will be assigned to it based on the setting of FLU_DEBUG. 72 """ 73 # parse what level it is set to based on FLU_DEBUG 74 # example: *:2,admin:4 75 global _FLU_DEBUG 76 global _levels 77 global _categories 78 79 level = 0 80 chunks = _FLU_DEBUG.split(',') 81 for chunk in chunks: 82 if not chunk: 83 continue 84 if ':' in chunk: 85 spec, value = chunk.split(':') 86 else: 87 spec = '*' 88 value = chunk 89 90 # our glob is unix filename style globbing, so cheat with fnmatch 91 # fnmatch.fnmatch didn't work for this, so don't use it 92 if category in fnmatch.filter((category, ), spec): 93 # we have a match, so set level based on string or int 94 if not value: 95 continue 96 try: 97 level = int(value) 98 except ValueError: # e.g. *; we default to most 99 level = 5 100 # store it 101 _categories[category] = level
102
103 -def getCategoryLevel(category):
104 """ 105 @param category: string 106 107 Get the debug level at which this category is being logged, adding it 108 if it wasn't registered yet. 109 """ 110 global _categories 111 if not _categories.has_key(category): 112 registerCategory(category) 113 return _categories[category]
114
115 -def _canShortcutLogging(category, level):
116 if _log_handlers: 117 # we have some loggers operating without filters, have to do 118 # everything 119 return False 120 else: 121 return level > getCategoryLevel(category)
122
123 -def scrubFilename(filename):
124 ''' 125 Scrub the filename of everything before 'flumotion' and'twisted' to make them shorter. 126 ''' 127 i = filename.rfind('flumotion') 128 if i != -1: 129 #filename = filename[i + len('flumotion') + 1:] 130 filename = filename[i:] 131 else: 132 # only pure twisted, not flumotion.twisted 133 i = filename.rfind('twisted') 134 if i != -1: 135 filename = filename[i:] 136 137 return filename
138
139 -def getFileLine(where=-1):
140 """ 141 Return the filename and line number for the given location. 142 143 If where is a negative integer, look for the code entry in the current 144 stack that is the given number of frames above this module. 145 If where is a function, look for the code entry of the function. 146 147 @param where: how many frames to go back up, or function 148 @type where: int (negative) or function 149 150 @return: tuple of (file, line) 151 @rtype: tuple of (str, int) 152 """ 153 co = None 154 lineno = None 155 156 if isinstance(where, types.FunctionType): 157 co = where.func_code 158 lineno = co.co_firstlineno 159 elif isinstance(where, types.MethodType): 160 co = where.im_func.func_code 161 lineno = co.co_firstlineno 162 else: 163 stackFrame = sys._getframe() 164 while stackFrame: 165 co = stackFrame.f_code 166 if not co.co_filename.endswith('log.py'): 167 # wind up the stack according to frame 168 while where < -1: 169 stackFrame = stackFrame.f_back 170 where += 1 171 co = stackFrame.f_code 172 lineno = stackFrame.f_lineno 173 break 174 stackFrame = stackFrame.f_back 175 176 if not co: 177 return "<unknown file>", 0 178 179 return scrubFilename(co.co_filename), lineno
180
181 -def ellipsize(o):
182 """ 183 Ellipsize the representation of the given object. 184 """ 185 r = repr(o) 186 if len(r) < 800: 187 return r 188 189 r = r[:60] + ' ... ' + r[-15:] 190 return r
191
192 -def getFormatArgs(startFormat, startArgs, endFormat, endArgs, args, kwargs):
193 """ 194 Helper function to create a format and args to use for logging. 195 This avoids needlessly interpolating variables. 196 """ 197 debugArgs = startArgs[:] 198 for a in args: 199 debugArgs.append(ellipsize(a)) 200 201 for items in kwargs.items(): 202 debugArgs.extend(items) 203 debugArgs.extend(endArgs) 204 format = startFormat \ 205 + ', '.join(('%s', ) * len(args)) \ 206 + ', '.join(('%s=%r, ', ) * len(kwargs)) \ 207 + endFormat 208 return format, debugArgs
209
210 -def doLog(level, object, category, format, args, where=-1, 211 file=None, line=None):
212 """ 213 @param where: what to log file and line number for; 214 -1 for one frame above log.py; -2 and down for higher up; 215 a function for a (future) code object 216 @type where: int or callable 217 @param file: file to show the message as coming from, if caller knows best 218 @type file: str 219 @param line: line to show the message as coming from, if caller knows best 220 @type line: int 221 222 @return: dict of calculated variables, if they needed calculating. 223 currently contains file and line; this prevents us from 224 doing this work in the caller when it isn't needed because 225 of the debug level 226 """ 227 ret = {} 228 229 if args: 230 message = format % args 231 else: 232 message = format 233 234 # first all the unlimited ones 235 if _log_handlers: 236 if file is None and line is None: 237 (file, line) = getFileLine(where=where) 238 ret['file'] = file 239 ret['line'] = line 240 for handler in _log_handlers: 241 try: 242 handler(level, object, category, file, line, message) 243 except TypeError: 244 raise SystemError, "handler %r raised a TypeError" % handler 245 246 if level > getCategoryLevel(category): 247 return ret 248 249 for handler in _log_handlers_limited: 250 # set this a second time, just in case there weren't unlimited 251 # loggers there before 252 if file is None and line is None: 253 (file, line) = getFileLine(where=where) 254 ret['file'] = file 255 ret['line'] = line 256 try: 257 handler(level, object, category, file, line, message) 258 except TypeError: 259 raise SystemError, "handler %r raised a TypeError" % handler 260 261 return ret
262
263 -def errorObject(object, cat, format, *args):
264 """ 265 Log a fatal error message in the given category. 266 This will also raise a L{flumotion.common.errors.SystemError}. 267 """ 268 doLog(ERROR, object, cat, format, args) 269 270 # we do the import here because having it globally causes weird import 271 # errors if our gstreactor also imports .log, which brings in errors 272 # and pb stuff 273 from flumotion.common.errors import SystemError 274 if args: 275 raise SystemError(format % args) 276 else: 277 raise SystemError(format)
278
279 -def warningObject(object, cat, format, *args):
280 """ 281 Log a warning message in the given category. 282 This is used for non-fatal problems. 283 """ 284 doLog(WARN, object, cat, format, args)
285
286 -def infoObject(object, cat, format, *args):
287 """ 288 Log an informational message in the given category. 289 """ 290 doLog(INFO, object, cat, format, args)
291
292 -def debugObject(object, cat, format, *args):
293 """ 294 Log a debug message in the given category. 295 """ 296 doLog(DEBUG, object, cat, format, args)
297
298 -def logObject(object, cat, format, *args):
299 """ 300 Log a log message. Used for debugging recurring events. 301 """ 302 doLog(LOG, object, cat, format, args)
303
304 -def error(cat, format, *args):
305 errorObject(None, cat, format, *args)
306
307 -def warning(cat, format, *args):
308 warningObject(None, cat, format, *args)
309
310 -def info(cat, format, *args):
311 infoObject(None, cat, format, *args)
312
313 -def debug(cat, format, *args):
314 debugObject(None, cat, format, *args)
315
316 -def log(cat, format, *args):
317 logObject(None, cat, format, *args)
318
319 -def warningFailure(failure, swallow=True):
320 """ 321 Log a warning about a Failure. Useful as an errback handler: 322 d.addErrback(warningFailure) 323 324 @param swallow: whether to swallow the failure or not 325 @type swallow: bool 326 """ 327 warning('', getFailureMessage(failure)) 328 if not swallow: 329 return failure
330
331 -class Loggable:
332 """ 333 Base class for objects that want to be able to log messages with 334 different level of severity. The levels are, in order from least 335 to most: log, debug, info, warning, error. 336 337 @cvar logCategory: Implementors can provide a category to log their 338 messages under. 339 """ 340 341 logCategory = 'default' 342
343 - def error(self, *args):
344 """Log an error. By default this will also raise an exception.""" 345 if _canShortcutLogging(self.logCategory, ERROR): 346 return 347 errorObject(self.logObjectName(), self.logCategory, 348 *self.logFunction(*args))
349
350 - def warning(self, *args):
351 """Log a warning. Used for non-fatal problems.""" 352 if _canShortcutLogging(self.logCategory, WARN): 353 return 354 warningObject(self.logObjectName(), self.logCategory, 355 *self.logFunction(*args))
356
357 - def info(self, *args):
358 """Log an informational message. Used for normal operation.""" 359 if _canShortcutLogging(self.logCategory, INFO): 360 return 361 infoObject(self.logObjectName(), self.logCategory, 362 *self.logFunction(*args))
363
364 - def debug(self, *args):
365 """Log a debug message. Used for debugging.""" 366 if _canShortcutLogging(self.logCategory, DEBUG): 367 return 368 debugObject(self.logObjectName(), self.logCategory, 369 *self.logFunction(*args))
370
371 - def log(self, *args):
372 """Log a log message. Used for debugging recurring events.""" 373 if _canShortcutLogging(self.logCategory, LOG): 374 return 375 logObject(self.logObjectName(), self.logCategory, 376 *self.logFunction(*args))
377
378 - def doLog(self, level, where, format, *args, **kwargs):
379 """ 380 Log a message at the given level, with the possibility of going 381 higher up in the stack. 382 383 @param level: log level 384 @type level: int 385 @param where: how many frames to go back from the last log frame; 386 or a function (to log for a future call) 387 @type where: int (negative), or function 388 389 @param kwargs: a dict of pre-calculated values from a previous 390 doLog call 391 392 @return: a dict of calculated variables, to be reused in a 393 call to doLog that should show the same location 394 @rtype: dict 395 """ 396 if _canShortcutLogging(self.logCategory, level): 397 return {} 398 args = self.logFunction(*args) 399 return doLog(level, self.logObjectName(), self.logCategory, 400 format, args, where=where, **kwargs)
401
402 - def warningFailure(self, failure, swallow=True):
403 """ 404 Log a warning about a Failure. Useful as an errback handler: 405 d.addErrback(self.warningFailure) 406 407 @param swallow: whether to swallow the failure or not 408 @type swallow: bool 409 """ 410 if _canShortcutLogging(self.logCategory, WARN): 411 if swallow: 412 return 413 return failure 414 warningObject(self.logObjectName(), self.logCategory, 415 *self.logFunction(getFailureMessage(failure))) 416 if not swallow: 417 return failure
418
419 - def logFunction(self, *args):
420 """Overridable log function. Default just returns passed message.""" 421 return args
422
423 - def logObjectName(self):
424 """Overridable object name function.""" 425 # cheat pychecker 426 for name in ['logName', 'name']: 427 if hasattr(self, name): 428 return getattr(self, name) 429 430 return None
431 432 # we need an object as the observer because startLoggingWithObserver 433 # expects a bound method
434 -class FluLogObserver(Loggable):
435 """ 436 Twisted log observer that integrates with Flumotion's logging. 437 """ 438 logCategory = "logobserver" 439
440 - def __init__(self):
441 self._ignoreErrors = []
442
443 - def emit(self, eventDict):
444 method = log # by default, lowest level 445 edm = eventDict['message'] 446 if not edm: 447 if eventDict['isError'] and eventDict.has_key('failure'): 448 f = eventDict['failure'] 449 for type in self._ignoreErrors: 450 r = f.check(type) 451 if r: 452 self.debug("Failure of type %r, ignoring" % type) 453 return 454 455 self.log("Failure %r" % f) 456 457 method = debug # tracebacks from errors at debug level 458 msg = "A twisted traceback occurred." 459 if getCategoryLevel("twisted") < WARN: 460 msg += " Run with debug level >= 2 to see the traceback." 461 # and an additional warning 462 warning('twisted', msg) 463 text = f.getTraceback() 464 print "\nTwisted traceback:\n" 465 print text 466 elif eventDict.has_key('format'): 467 text = eventDict['format'] % eventDict 468 else: 469 # we don't know how to log this 470 return 471 else: 472 text = ' '.join(map(str, edm)) 473 474 fmtDict = { 'system': eventDict['system'], 475 'text': text.replace("\n", "\n\t") 476 } 477 msgStr = " [%(system)s] %(text)s\n" % fmtDict 478 # because msgstr can contain %, as in a backtrace, make sure we 479 # don't try to splice it 480 method('twisted', msgStr)
481
482 - def ignoreErrors(self, *types):
483 for type in types: 484 self._ignoreErrors.append(type)
485
486 - def clearIgnores(self):
487 self._ignoreErrors = []
488 489 # make a singleton 490 __theFluLogObserver = None 491
492 -def _getTheFluLogObserver():
493 # used internally and in test 494 global __theFluLogObserver 495 496 if not __theFluLogObserver: 497 __theFluLogObserver = FluLogObserver() 498 499 return __theFluLogObserver
500
501 -def stderrHandler(level, object, category, file, line, message):
502 """ 503 A log handler that writes to stderr. 504 505 @type level: string 506 @type object: string (or None) 507 @type category: string 508 @type message: string 509 """ 510 511 o = "" 512 if object: 513 o = '"' + object + '"' 514 515 where = "(%s:%d)" % (file, line) 516 517 try: 518 # level pid object cat time 519 # 5 + 1 + 7 + 1 + 32 + 1 + 17 + 1 + 15 == 80 520 sys.stderr.write('%-5s [%5d] %-32s %-17s %-15s ' % ( 521 getLevelName(level), os.getpid(), o, category, 522 time.strftime("%b %d %H:%M:%S"))) 523 sys.stderr.write('%-4s %s %s\n' % ("", message, where)) 524 525 # old: 5 + 1 + 20 + 1 + 12 + 1 + 32 + 1 + 7 == 80 526 #sys.stderr.write('%-5s %-20s %-12s %-32s [%5d] %-4s %-15s %s\n' % ( 527 # level, o, category, where, os.getpid(), 528 # "", time.strftime("%b %d %H:%M:%S"), message)) 529 sys.stderr.flush() 530 except IOError, e: 531 if e.errno == errno.EPIPE: 532 # if our output is closed, exit; e.g. when logging over an 533 # ssh connection and the ssh connection is closed 534 os._exit(os.EX_OSERR)
535 # otherwise ignore it, there's nothing you can do 536
537 -def addLogHandler(func, limited=True):
538 """ 539 Add a custom log handler. 540 541 @param func: a function object 542 with prototype (level, object, category, message) 543 where level is either ERROR, WARN, INFO, DEBUG, or 544 LOG, and the rest of the arguments are strings or 545 None. Use getLevelName(level) to get a printable 546 name for the log level. 547 @type func: a callable function 548 @type limited: boolean 549 @param limited: whether to automatically filter based on FLU_DEBUG 550 """ 551 552 if not callable(func): 553 raise TypeError, "func must be callable" 554 555 if limited: 556 _log_handlers_limited.append(func) 557 else: 558 _log_handlers.append(func)
559
560 -def init():
561 """ 562 Initialize the logging system and parse the FLU_DEBUG environment variable. 563 Needs to be called before starting the actual application. 564 """ 565 global _initialized 566 567 if _initialized: 568 return 569 570 if os.environ.has_key('FLU_DEBUG'): 571 # install a log handler that uses the value of FLU_DEBUG 572 setFluDebug(os.environ['FLU_DEBUG']) 573 addLogHandler(stderrHandler, limited=True) 574 575 _initialized = True
576 577 _stdout = None 578 _stderr = None
579 -def reopenOutputFiles():
580 """ 581 Reopens the stdout and stderr output files, as set by 582 L{flumotion.common.log.outputToFiles}. 583 """ 584 if not (_stdout and _stderr): 585 debug('log', 'told to reopen log files, but log files not set') 586 return 587 588 oldmask = os.umask(0026) 589 try: 590 so = open(_stdout, 'a+') 591 se = open(_stderr, 'a+', 0) 592 finally: 593 os.umask(oldmask) 594 595 os.dup2(so.fileno(), sys.stdout.fileno()) 596 os.dup2(se.fileno(), sys.stderr.fileno()) 597 598 debug('log', 'opened log %r', _stderr)
599
600 -def outputToFiles(stdout, stderr):
601 """ 602 Redirect stdout and stderr to named files. 603 604 Records the file names so that a future call to reopenOutputFiles() 605 can open the same files. Installs a SIGHUP handler that will reopen 606 the output files. 607 608 Note that stderr is opened unbuffered, so if it shares a file with 609 stdout then interleaved output may not appear in the order that you 610 expect. 611 """ 612 global _stdout, _stderr 613 _stdout, _stderr = stdout, stderr 614 reopenOutputFiles() 615 616 def sighup(signum, frame): 617 info('log', "Received SIGHUP, reopening logs") 618 reopenOutputFiles()
619 620 debug('log', 'installing SIGHUP handler') 621 import signal 622 signal.signal(signal.SIGHUP, sighup) 623 624 _initializedTwisted = False 625
626 -def logTwisted():
627 """ 628 Integrate twisted's logger with Flumotion's logger. 629 630 This is done in a separate method because calling this imports and sets 631 up a reactor. Since we want basic logging working before choosing a 632 reactor, we need to separate these. 633 """ 634 global _initializedTwisted 635 636 if _initializedTwisted: 637 return 638 639 debug('log', 'Integrating twisted logger') 640 641 # integrate twisted's logging with us 642 from twisted.python import log as tlog 643 644 # this call imports the reactor 645 # that is why we do this in a separate method 646 from twisted.spread import pb 647 648 # we don't want logs for pb.Error types since they 649 # are specifically raised to be handled on the other side 650 observer = _getTheFluLogObserver() 651 observer.ignoreErrors([pb.Error,]) 652 tlog.startLoggingWithObserver(observer.emit, False) 653 654 _initializedTwisted = True
655
656 -def reset():
657 """ 658 Resets the logging system, removing all log handlers. 659 """ 660 global _log_handlers, _log_handlers_limited, _initialized 661 662 _log_handlers = [] 663 _log_handlers_limited = [] 664 _initialized = False
665
666 -def setFluDebug(string):
667 """Set the FLU_DEBUG string. This controls the log output.""" 668 global _FLU_DEBUG 669 global _categories 670 671 _FLU_DEBUG = string 672 debug('log', "FLU_DEBUG set to %s" % _FLU_DEBUG) 673 674 # reparse all already registered category levels 675 for category in _categories: 676 registerCategory(category)
677
678 -def getExceptionMessage(exception, frame=-1, filename=None):
679 """ 680 Return a short message based on an exception, useful for debugging. 681 Tries to find where the exception was triggered. 682 """ 683 stack = traceback.extract_tb(sys.exc_info()[2]) 684 if filename: 685 stack = [f for f in stack if f[0].find(filename) > -1] 686 #import code; code.interact(local=locals()) 687 (filename, line, func, text) = stack[frame] 688 filename = scrubFilename(filename) 689 exc = exception.__class__.__name__ 690 msg = "" 691 # a shortcut to extract a useful message out of most flumotion errors 692 # for now 693 if str(exception): 694 msg = ": %s" % str(exception) 695 return "exception %(exc)s at %(filename)s:%(line)s: %(func)s()%(msg)s" % locals()
696
697 -def getFailureMessage(failure):
698 """ 699 Return a short message based on L{twisted.python.failure.Failure}. 700 Tries to find where the exception was triggered. 701 """ 702 exc = str(failure.type) 703 msg = failure.getErrorMessage() 704 if len(failure.frames) == 0: 705 return "failure %(exc)s: %(msg)s" % locals() 706 707 (func, filename, line, some, other) = failure.frames[-1] 708 filename = scrubFilename(filename) 709 return "failure %(exc)s at %(filename)s:%(line)s: %(func)s(): %(msg)s" % locals()
710