# CC'd from 'pitivi/log/loggable.py' # # Copyright (c) 2009, Alessandro Decina # # This program is free software; you can redistribute it and/or # modify it under the terms of the GNU Lesser General Public # License as published by the Free Software Foundation; either # version 2.1 of the License, or (at your option) any later version. # # This program is distributed in the hope that it will be useful, # but WITHOUT ANY WARRANTY; without even the implied warranty of # MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the GNU # Lesser General Public License for more details. # # You should have received a copy of the GNU Lesser General Public # License along with this program; if not, write to the # Free Software Foundation, Inc., 51 Franklin St, Fifth Floor, # Boston, MA 02110-1301, USA. import errno import sys import re import os import fnmatch import time import types import traceback import thread # environment variables controlling levels for each category _DEBUG = "*:1" # name of the environment variable controlling our logging _ENV_VAR_NAME = None # package names we should scrub filenames for _PACKAGE_SCRUB_LIST = [] # dynamic dictionary of categories already seen and their level _categories = {} # log handlers registered _log_handlers = [] _log_handlers_limited = [] _initialized = False _stdout = None _stderr = None _old_hup_handler = None # public log levels (ERROR, WARN, FIXME, INFO, DEBUG, LOG) = range(1, 7) COLORS = {ERROR: 'RED', WARN: 'YELLOW', FIXME: 'MAGENTA', INFO: 'GREEN', DEBUG: 'BLUE', LOG: 'CYAN'} _FORMATTED_LEVELS = [] _LEVEL_NAMES = ['ERROR', 'WARN', 'FIXME', 'INFO', 'DEBUG', 'LOG'] class TerminalController(object): """ A class that can be used to portably generate formatted output to a terminal. `TerminalController` defines a set of instance variables whose values are initialized to the control sequence necessary to perform a given action. These can be simply included in normal output to the terminal: >>> term = TerminalController() >>> print 'This is '+term.GREEN+'green'+term.NORMAL Alternatively, the `render()` method can used, which replaces '${action}' with the string required to perform 'action': >>> term = TerminalController() >>> print term.render('This is ${GREEN}green${NORMAL}') If the terminal doesn't support a given action, then the value of the corresponding instance variable will be set to ''. As a result, the above code will still work on terminals that do not support color, except that their output will not be colored. Also, this means that you can test whether the terminal supports a given action by simply testing the truth value of the corresponding instance variable: >>> term = TerminalController() >>> if term.CLEAR_SCREEN: ... print 'This terminal supports clearning the screen.' Finally, if the width and height of the terminal are known, then they will be stored in the `COLS` and `LINES` attributes. """ # Cursor movement: BOL = '' # : Move the cursor to the beginning of the line UP = '' # : Move the cursor up one line DOWN = '' # : Move the cursor down one line LEFT = '' # : Move the cursor left one char RIGHT = '' # : Move the cursor right one char # Deletion: CLEAR_SCREEN = '' # : Clear the screen and move to home position CLEAR_EOL = '' # : Clear to the end of the line. CLEAR_BOL = '' # : Clear to the beginning of the line. CLEAR_EOS = '' # : Clear to the end of the screen # Output modes: BOLD = '' # : Turn on bold mode BLINK = '' # : Turn on blink mode DIM = '' # : Turn on half-bright mode REVERSE = '' # : Turn on reverse-video mode NORMAL = '' # : Turn off all modes # Cursor display: HIDE_CURSOR = '' # : Make the cursor invisible SHOW_CURSOR = '' # : Make the cursor visible # Terminal size: COLS = None # : Width of the terminal (None for unknown) LINES = None # : Height of the terminal (None for unknown) # Foreground colors: BLACK = BLUE = GREEN = CYAN = RED = MAGENTA = YELLOW = WHITE = '' # Background colors: BG_BLACK = BG_BLUE = BG_GREEN = BG_CYAN = '' BG_RED = BG_MAGENTA = BG_YELLOW = BG_WHITE = '' _STRING_CAPABILITIES = """ BOL=cr UP=cuu1 DOWN=cud1 LEFT=cub1 RIGHT=cuf1 CLEAR_SCREEN=clear CLEAR_EOL=el CLEAR_BOL=el1 CLEAR_EOS=ed BOLD=bold BLINK=blink DIM=dim REVERSE=rev UNDERLINE=smul NORMAL=sgr0 HIDE_CURSOR=cinvis SHOW_CURSOR=cnorm""".split() _COLORS = """BLACK BLUE GREEN CYAN RED MAGENTA YELLOW WHITE""".split() _ANSICOLORS = "BLACK RED GREEN YELLOW BLUE MAGENTA CYAN WHITE".split() def __init__(self, term_stream=sys.stdout): """ Create a `TerminalController` and initialize its attributes with appropriate values for the current terminal. `term_stream` is the stream that will be used for terminal output; if this stream is not a tty, then the terminal is assumed to be a dumb terminal (i.e., have no capabilities). """ # Curses isn't available on all platforms try: import curses except ImportError: return # If the stream isn't a tty, then assume it has no capabilities. if not term_stream.isatty(): return # Check the terminal type. If we fail, then assume that the # terminal has no capabilities. try: curses.setupterm() except: return # Look up numeric capabilities. self.COLS = curses.tigetnum('cols') self.LINES = curses.tigetnum('lines') # Look up string capabilities. for capability in self._STRING_CAPABILITIES: (attrib, cap_name) = capability.split('=') setattr(self, attrib, self._tigetstr(cap_name) or '') # Colors set_fg = self._tigetstr('setf') if set_fg: for i, color in zip(range(len(self._COLORS)), self._COLORS): setattr(self, color, curses.tparm(set_fg, i) or '') set_fg_ansi = self._tigetstr('setaf') if set_fg_ansi: for i, color in zip(range(len(self._ANSICOLORS)), self._ANSICOLORS): setattr(self, color, curses.tparm(set_fg_ansi, i) or '') set_bg = self._tigetstr('setb') if set_bg: for i, color in zip(range(len(self._COLORS)), self._COLORS): setattr(self, 'BG_' + color, curses.tparm(set_bg, i) or '') set_bg_ansi = self._tigetstr('setab') if set_bg_ansi: for i, color in zip(range(len(self._ANSICOLORS)), self._ANSICOLORS): setattr( self, 'BG_' + color, curses.tparm(set_bg_ansi, i) or '') def _tigetstr(self, cap_name): # String capabilities can include "delays" of the form "$<2>". # For any modern terminal, we should be able to just ignore # these, so strip them out. import curses cap = curses.tigetstr(cap_name) or '' return re.sub(r'\$<\d+>[/*]?', '', cap) def render(self, template): """ Replace each $-substitutions in the given template string with the corresponding terminal control string (if it's defined) or '' (if it's not). """ return re.sub(r'\$\$|\${\w+}', self._render_sub, template) def _render_sub(self, match): s = match.group() if s == '$$': return s else: return getattr(self, s[2:-1]) # # Example use case: progress bar # class ProgressBar: """ A 3-line progress bar, which looks like:: Header 20% [===========----------------------------------] progress message The progress bar is colored, if the terminal supports color output; and adjusts to the width of the terminal. """ BAR = '%3d%% ${GREEN}[${BOLD}%s%s${NORMAL}${GREEN}]${NORMAL}\n' HEADER = '${BOLD}${CYAN}%s${NORMAL}\n\n' def __init__(self, term, header): self.term = term if not (self.term.CLEAR_EOL and self.term.UP and self.term.BOL): raise ValueError("Terminal isn't capable enough -- you " "should use a simpler progress dispaly.") self.width = self.term.COLS or 75 self.bar = term.render(self.BAR) self.header = self.term.render(self.HEADER % header.center(self.width)) self.cleared = 1 # : true if we haven't drawn the bar yet. self.update(0, '') def update(self, percent, message): if self.cleared: sys.stdout.write(self.header) self.cleared = 0 n = int((self.width - 10) * percent) sys.stdout.write( self.term.BOL + self.term.UP + self.term.CLEAR_EOL + (self.bar % (100 * percent, '=' * n, '-' * (self.width - 10 - n))) + self.term.CLEAR_EOL + message.center(self.width)) def clear(self): if not self.cleared: sys.stdout.write(self.term.BOL + self.term.CLEAR_EOL + self.term.UP + self.term.CLEAR_EOL + self.term.UP + self.term.CLEAR_EOL) self.cleared = 1 def getLevelName(level): """ Return the name of a log level. @param level: The level we want to know the name @type level: int @return: The name of the level @rtype: str """ assert isinstance(level, int) and level > 0 and level < 6, \ TypeError("Bad debug level") return getLevelNames()[level - 1] def getLevelNames(): """ Return a list with the level names @return: A list with the level names @rtype: list of str """ return _LEVEL_NAMES def getLevelInt(levelName): """ Return the integer value of the levelName. @param levelName: The string value of the level name @type levelName: str @return: The value of the level name we are interested in. @rtype: int """ assert isinstance(levelName, str) and levelName in getLevelNames(), \ "Bad debug level name" return getLevelNames().index(levelName) + 1 def getFormattedLevelName(level): assert isinstance(level, int) and level > 0 and level < len(_LEVEL_NAMES) + 1, \ TypeError("Bad debug level") return _FORMATTED_LEVELS[level - 1] def registerCategory(category): """ Register a given category in the debug system. A level will be assigned to it based on previous calls to setDebug. """ # parse what level it is set to based on _DEBUG # example: *:2,admin:4 global _DEBUG global _levels global _categories level = 0 chunks = _DEBUG.split(',') for chunk in chunks: if not chunk: continue if ':' in chunk: spec, value = chunk.split(':') else: spec = '*' value = chunk # our glob is unix filename style globbing, so cheat with fnmatch # fnmatch.fnmatch didn't work for this, so don't use it if category in fnmatch.filter((category, ), spec): # we have a match, so set level based on string or int if not value: continue try: level = int(value) except ValueError: # e.g. *; we default to most level = 5 # store it _categories[category] = level def getCategoryLevel(category): """ @param category: string Get the debug level at which this category is being logged, adding it if it wasn't registered yet. """ global _categories if not category in _categories: registerCategory(category) return _categories[category] def setLogSettings(state): """Update the current log settings. This can restore an old saved log settings object returned by getLogSettings @param state: the settings to set """ global _DEBUG global _log_handlers global _log_handlers_limited (_DEBUG, _categories, _log_handlers, _log_handlers_limited) = state for category in _categories: registerCategory(category) def getLogSettings(): """Fetches the current log settings. The returned object can be sent to setLogSettings to restore the returned settings @returns: the current settings """ return (_DEBUG, _categories, _log_handlers, _log_handlers_limited) def _canShortcutLogging(category, level): if _log_handlers: # we have some loggers operating without filters, have to do # everything return False else: return level > getCategoryLevel(category) def scrubFilename(filename): ''' Scrub the filename to a relative path for all packages in our scrub list. ''' global _PACKAGE_SCRUB_LIST for package in _PACKAGE_SCRUB_LIST: i = filename.rfind(package) if i > -1: return filename[i:] return filename def getFileLine(where=-1): """ Return the filename and line number for the given location. If where is a negative integer, look for the code entry in the current stack that is the given number of frames above this module. If where is a function, look for the code entry of the function. @param where: how many frames to go back up, or function @type where: int (negative) or function @return: tuple of (file, line) @rtype: tuple of (str, int) """ co = None lineno = None name = None if isinstance(where, types.FunctionType): co = where.func_code lineno = co.co_firstlineno name = co.co_name elif isinstance(where, types.MethodType): co = where.im_func.func_code lineno = co.co_firstlineno name = co.co_name else: stackFrame = sys._getframe() while stackFrame: co = stackFrame.f_code if not co.co_filename.endswith('loggable.py'): # wind up the stack according to frame while where < -1: stackFrame = stackFrame.f_back where += 1 co = stackFrame.f_code lineno = stackFrame.f_lineno name = co.co_name break stackFrame = stackFrame.f_back if not co: return "", 0 return scrubFilename(co.co_filename), lineno, name def ellipsize(o): """ Ellipsize the representation of the given object. """ r = repr(o) if len(r) < 800: return r r = r[:60] + ' ... ' + r[-15:] return r def getFormatArgs(startFormat, startArgs, endFormat, endArgs, args, kwargs): """ Helper function to create a format and args to use for logging. This avoids needlessly interpolating variables. """ debugArgs = startArgs[:] for a in args: debugArgs.append(ellipsize(a)) for items in kwargs.items(): debugArgs.extend(items) debugArgs.extend(endArgs) format = startFormat \ + ', '.join(('%s', ) * len(args)) \ + (kwargs and ', ' or '') \ + ', '.join(('%s=%r', ) * len(kwargs)) \ + endFormat return format, debugArgs def doLog(level, object, category, format, args, where=-1, filePath=None, line=None): """ @param where: what to log file and line number for; -1 for one frame above log.py; -2 and down for higher up; a function for a (future) code object @type where: int or callable @param filePath: file to show the message as coming from, if caller knows best @type filePath: str @param line: line to show the message as coming from, if caller knows best @type line: int @return: dict of calculated variables, if they needed calculating. currently contains file and line; this prevents us from doing this work in the caller when it isn't needed because of the debug level """ ret = {} if args: message = format % args else: message = format # first all the unlimited ones if _log_handlers: if filePath is None and line is None: (filePath, line, funcname) = getFileLine(where=where) ret['filePath'] = filePath ret['line'] = line if funcname: message = "\033[00m\033[32;01m%s:\033[00m %s" % (funcname, message) for handler in _log_handlers: try: handler(level, object, category, file, line, message) except TypeError, e: raise SystemError("handler %r raised a TypeError: %s" % ( handler, getExceptionMessage(e))) if level > getCategoryLevel(category): return ret if _log_handlers_limited: if filePath is None and line is None: (filePath, line, funcname) = getFileLine(where=where) ret['filePath'] = filePath ret['line'] = line if funcname: message = "\033[00m\033[32;01m%s:\033[00m %s" % (funcname, message) for handler in _log_handlers_limited: # set this a second time, just in case there weren't unlimited # loggers there before try: handler(level, object, category, filePath, line, message) except TypeError: raise SystemError("handler %r raised a TypeError" % handler) return ret def errorObject(object, cat, format, *args): """ Log a fatal error message in the given category. This will also raise a L{SystemExit}. """ doLog(ERROR, object, cat, format, args) # we do the import here because having it globally causes weird import # errors if our gstreactor also imports .log, which brings in errors # and pb stuff if args: raise SystemExit(format % args) else: raise SystemExit(format) def warningObject(object, cat, format, *args): """ Log a warning message in the given category. This is used for non-fatal problems. """ doLog(WARN, object, cat, format, args) def fixmeObject(object, cat, format, *args): """ Log a fixme message in the given category. This is used for not implemented codepaths or known issues in the code """ doLog(FIXME, object, cat, format, args) def infoObject(object, cat, format, *args): """ Log an informational message in the given category. """ doLog(INFO, object, cat, format, args) def debugObject(object, cat, format, *args): """ Log a debug message in the given category. """ doLog(DEBUG, object, cat, format, args) def logObject(object, cat, format, *args): """ Log a log message. Used for debugging recurring events. """ doLog(LOG, object, cat, format, args) def safeprintf(file, format, *args): """Write to a file object, ignoring errors. """ try: if args: file.write(format % args) else: file.write(format) except IOError, e: if e.errno == errno.EPIPE: # if our output is closed, exit; e.g. when logging over an # ssh connection and the ssh connection is closed os._exit(os.EX_OSERR) # otherwise ignore it, there's nothing you can do def stderrHandler(level, object, category, file, line, message): """ A log handler that writes to stderr. The output will be different depending the value of "_enableCrackOutput"; in Pitivi's case, that is True when the GST_DEBUG env var is defined. @type level: string @type object: string (or None) @type category: string @type message: string """ # Make the file path more compact for readability file = os.path.relpath(file) where = "(%s:%d)" % (file, line) # If GST_DEBUG is not set, we can assume only PITIVI_DEBUG is set, so don't # show a bazillion of debug details that are not relevant to Pitivi. if not _enableCrackOutput: safeprintf(sys.stderr, '%s %-8s %-17s %-2s %s %s\n', getFormattedLevelName(level), time.strftime("%H:%M:%S"), category, "", message, where) else: o = "" if object: o = '"' + object + '"' # level pid object cat time # 5 + 1 + 7 + 1 + 32 + 1 + 17 + 1 + 15 == 80 safeprintf( sys.stderr, '%s [%5d] [0x%12x] %-32s %-17s %-15s %-4s %s %s\n', getFormattedLevelName( level), os.getpid(), thread.get_ident(), o[:32], category, time.strftime("%b %d %H:%M:%S"), "", message, where) sys.stderr.flush() def _preformatLevels(noColorEnvVarName): format = '%-5s' if (noColorEnvVarName is not None and (noColorEnvVarName not in os.environ or not os.environ[noColorEnvVarName])): t = TerminalController() formatter = lambda level: ''.join((t.BOLD, getattr(t, COLORS[level]), format % (_LEVEL_NAMES[level - 1], ), t.NORMAL)) else: formatter = lambda level: format % (_LEVEL_NAMES[level - 1], ) for level in ERROR, WARN, FIXME, INFO, DEBUG, LOG: _FORMATTED_LEVELS.append(formatter(level)) # "public" useful API # setup functions def init(envVarName, enableColorOutput=False, enableCrackOutput=True): """ Initialize the logging system and parse the environment variable of the given name. Needs to be called before starting the actual application. """ global _initialized global _enableCrackOutput _enableCrackOutput = enableCrackOutput if _initialized: return global _ENV_VAR_NAME _ENV_VAR_NAME = envVarName if enableColorOutput: _preformatLevels(envVarName + "_NO_COLOR") else: _preformatLevels(None) if envVarName in os.environ: # install a log handler that uses the value of the environment var setDebug(os.environ[envVarName]) addLimitedLogHandler(stderrHandler) _initialized = True def setDebug(string): """Set the DEBUG string. This controls the log output.""" global _DEBUG global _ENV_VAR_NAME global _categories _DEBUG = string debug('log', "%s set to %s" % (_ENV_VAR_NAME, _DEBUG)) # reparse all already registered category levels for category in _categories: registerCategory(category) def getDebug(): """ Returns the currently active DEBUG string. @rtype: str """ global _DEBUG return _DEBUG def setPackageScrubList(*packages): """ Set the package names to scrub from filenames. Filenames from these paths in log messages will be scrubbed to their relative file path instead of the full absolute path. @type packages: list of str """ global _PACKAGE_SCRUB_LIST _PACKAGE_SCRUB_LIST = packages def reset(): """ Resets the logging system, removing all log handlers. """ global _log_handlers, _log_handlers_limited, _initialized _log_handlers = [] _log_handlers_limited = [] _initialized = False def addLogHandler(func): """ Add a custom log handler. @param func: a function object with prototype (level, object, category, message) where level is either ERROR, WARN, INFO, DEBUG, or LOG, and the rest of the arguments are strings or None. Use getLevelName(level) to get a printable name for the log level. @type func: a callable function @raises TypeError: if func is not a callable """ if not callable(func): raise TypeError("func must be callable") if func not in _log_handlers: _log_handlers.append(func) def addLimitedLogHandler(func): """ Add a custom log handler. @param func: a function object with prototype (level, object, category, message) where level is either ERROR, WARN, INFO, DEBUG, or LOG, and the rest of the arguments are strings or None. Use getLevelName(level) to get a printable name for the log level. @type func: a callable function @raises TypeError: TypeError if func is not a callable """ if not callable(func): raise TypeError("func must be callable") if func not in _log_handlers_limited: _log_handlers_limited.append(func) def removeLogHandler(func): """ Remove a registered log handler. @param func: a function object with prototype (level, object, category, message) where level is either ERROR, WARN, INFO, DEBUG, or LOG, and the rest of the arguments are strings or None. Use getLevelName(level) to get a printable name for the log level. @type func: a callable function @raises ValueError: if func is not registered """ _log_handlers.remove(func) def removeLimitedLogHandler(func): """ Remove a registered limited log handler. @param func: a function object with prototype (level, object, category, message) where level is either ERROR, WARN, INFO, DEBUG, or LOG, and the rest of the arguments are strings or None. Use getLevelName(level) to get a printable name for the log level. @type func: a callable function @raises ValueError: if func is not registered """ _log_handlers_limited.remove(func) # public log functions def error(cat, format, *args): errorObject(None, cat, format, *args) def warning(cat, format, *args): warningObject(None, cat, format, *args) def fixme(cat, format, *args): fixmeObject(None, cat, format, *args) def info(cat, format, *args): infoObject(None, cat, format, *args) def debug(cat, format, *args): debugObject(None, cat, format, *args) def log(cat, format, *args): logObject(None, cat, format, *args) # public utility functions def getExceptionMessage(exception, frame=-1, filename=None): """ Return a short message based on an exception, useful for debugging. Tries to find where the exception was triggered. """ stack = traceback.extract_tb(sys.exc_info()[2]) if filename: stack = [f for f in stack if f[0].find(filename) > -1] #import code; code.interact(local=locals()) (filename, line, func, text) = stack[frame] filename = scrubFilename(filename) exc = exception.__class__.__name__ msg = "" # a shortcut to extract a useful message out of most exceptions # for now if str(exception): msg = ": %s" % str(exception) return "exception %(exc)s at %(filename)s:%(line)s: %(func)s()%(msg)s" \ % locals() def reopenOutputFiles(): """ Reopens the stdout and stderr output files, as set by L{outputToFiles}. """ if not _stdout and not _stderr: debug('log', 'told to reopen log files, but log files not set') return def reopen(name, fileno, *args): oldmask = os.umask(0026) try: f = open(name, 'a+', *args) finally: os.umask(oldmask) os.dup2(f.fileno(), fileno) if _stdout: reopen(_stdout, sys.stdout.fileno()) if _stderr: reopen(_stderr, sys.stderr.fileno(), 0) debug('log', 'opened log %r', _stderr) def outputToFiles(stdout=None, stderr=None): """ Redirect stdout and stderr to named files. Records the file names so that a future call to reopenOutputFiles() can open the same files. Installs a SIGHUP handler that will reopen the output files. Note that stderr is opened unbuffered, so if it shares a file with stdout then interleaved output may not appear in the order that you expect. """ global _stdout, _stderr, _old_hup_handler _stdout, _stderr = stdout, stderr reopenOutputFiles() def sighup(signum, frame): info('log', "Received SIGHUP, reopening logs") reopenOutputFiles() if _old_hup_handler: info('log', "Calling old SIGHUP hander") _old_hup_handler(signum, frame) debug('log', 'installing SIGHUP handler') import signal handler = signal.signal(signal.SIGHUP, sighup) if handler == signal.SIG_DFL or handler == signal.SIG_IGN: _old_hup_handler = None else: _old_hup_handler = handler # base class for loggable objects class BaseLoggable(object): """ Base class for objects that want to be able to log messages with different level of severity. The levels are, in order from least to most: log, debug, info, warning, error. @cvar logCategory: Implementors can provide a category to log their messages under. """ def writeMarker(self, marker, level): """ Sets a marker that written to the logs. Setting this marker to multiple elements at a time helps debugging. @param marker: A string write to the log. @type marker: str @param level: The log level. It can be log.WARN, log.INFO, log.DEBUG, log.ERROR or log.LOG. @type level: int """ logHandlers = {WARN: self.warning, INFO: self.info, DEBUG: self.debug, ERROR: self.error, LOG: self.log} logHandler = logHandlers.get(level) if logHandler: logHandler('%s', marker) def error(self, *args): """Log an error. By default this will also raise an exception.""" if _canShortcutLogging(self.logCategory, ERROR): return errorObject(self.logObjectName(), self.logCategory, *self.logFunction(*args)) def warning(self, *args): """Log a warning. Used for non-fatal problems.""" if _canShortcutLogging(self.logCategory, WARN): return warningObject( self.logObjectName(), self.logCategory, *self.logFunction(*args)) def fixme(self, *args): """Log a fixme. Used for FIXMEs .""" if _canShortcutLogging(self.logCategory, FIXME): return fixmeObject(self.logObjectName(), self.logCategory, *self.logFunction(*args)) def info(self, *args): """Log an informational message. Used for normal operation.""" if _canShortcutLogging(self.logCategory, INFO): return infoObject(self.logObjectName(), self.logCategory, *self.logFunction(*args)) def debug(self, *args): """Log a debug message. Used for debugging.""" if _canShortcutLogging(self.logCategory, DEBUG): return debugObject(self.logObjectName(), self.logCategory, *self.logFunction(*args)) def log(self, *args): """Log a log message. Used for debugging recurring events.""" if _canShortcutLogging(self.logCategory, LOG): return logObject(self.logObjectName(), self.logCategory, *self.logFunction(*args)) def doLog(self, level, where, format, *args, **kwargs): """ Log a message at the given level, with the possibility of going higher up in the stack. @param level: log level @type level: int @param where: how many frames to go back from the last log frame; or a function (to log for a future call) @type where: int (negative), or function @param kwargs: a dict of pre-calculated values from a previous doLog call @return: a dict of calculated variables, to be reused in a call to doLog that should show the same location @rtype: dict """ if _canShortcutLogging(self.logCategory, level): return {} args = self.logFunction(*args) return doLog(level, self.logObjectName(), self.logCategory, format, args, where=where, **kwargs) def warningFailure(self, failure, swallow=True): """ Log a warning about a Twisted Failure. Useful as an errback handler: d.addErrback(self.warningFailure) @param swallow: whether to swallow the failure or not @type swallow: bool """ if _canShortcutLogging(self.logCategory, WARN): if swallow: return return failure warningObject(self.logObjectName(), self.logCategory, *self.logFunction(getFailureMessage(failure))) if not swallow: return failure def logFunction(self, *args): """Overridable log function. Default just returns passed message.""" return args def logObjectName(self): """Overridable object name function.""" # cheat pychecker for name in ['logName', 'name']: if hasattr(self, name): return getattr(self, name) return None def handleException(self, exc): self.warning(getExceptionMessage(exc)) # Twisted helper stuff # private stuff _initializedTwisted = False # make a singleton __theTwistedLogObserver = None def _getTheTwistedLogObserver(): # used internally and in test global __theTwistedLogObserver if not __theTwistedLogObserver: __theTwistedLogObserver = TwistedLogObserver() return __theTwistedLogObserver # public helper methods def getFailureMessage(failure): """ Return a short message based on L{twisted.python.failure.Failure}. Tries to find where the exception was triggered. """ exc = str(failure.type) msg = failure.getErrorMessage() if len(failure.frames) == 0: return "failure %(exc)s: %(msg)s" % locals() (func, filename, line, some, other) = failure.frames[-1] filename = scrubFilename(filename) return "failure %(exc)s at %(filename)s:%(line)s: %(func)s(): %(msg)s" % locals() def warningFailure(failure, swallow=True): """ Log a warning about a Failure. Useful as an errback handler: d.addErrback(warningFailure) @param swallow: whether to swallow the failure or not @type swallow: bool """ warning('', getFailureMessage(failure)) if not swallow: return failure def logTwisted(): """ Integrate twisted's logger with our logger. This is done in a separate method because calling this imports and sets up a reactor. Since we want basic logging working before choosing a reactor, we need to separate these. """ global _initializedTwisted if _initializedTwisted: return debug('log', 'Integrating twisted logger') # integrate twisted's logging with us from twisted.python import log as tlog # this call imports the reactor # that is why we do this in a separate method from twisted.spread import pb # we don't want logs for pb.Error types since they # are specifically raised to be handled on the other side observer = _getTheTwistedLogObserver() observer.ignoreErrors([pb.Error, ]) tlog.startLoggingWithObserver(observer.emit, False) _initializedTwisted = True # we need an object as the observer because startLoggingWithObserver # expects a bound method class TwistedLogObserver(BaseLoggable): """ Twisted log observer that integrates with our logging. """ logCategory = "logobserver" def __init__(self): self._ignoreErrors = [] # Failure types def emit(self, eventDict): method = log # by default, lowest level edm = eventDict['message'] if not edm: if eventDict['isError'] and 'failure' in eventDict: f = eventDict['failure'] for failureType in self._ignoreErrors: r = f.check(failureType) if r: self.debug("Failure of type %r, ignoring", failureType) return self.log("Failure %r" % f) method = debug # tracebacks from errors at debug level msg = "A twisted traceback occurred." if getCategoryLevel("twisted") < WARN: msg += " Run with debug level >= 2 to see the traceback." # and an additional warning warning('twisted', msg) text = f.getTraceback() safeprintf(sys.stderr, "\nTwisted traceback:\n") safeprintf(sys.stderr, text + '\n') elif 'format' in eventDict: text = eventDict['format'] % eventDict else: # we don't know how to log this return else: text = ' '.join(map(str, edm)) fmtDict = {'system': eventDict['system'], 'text': text.replace("\n", "\n\t")} msgStr = " [%(system)s] %(text)s\n" % fmtDict # because msgstr can contain %, as in a backtrace, make sure we # don't try to splice it method('twisted', msgStr) def ignoreErrors(self, *types): for failureType in types: self._ignoreErrors.append(failureType) def clearIgnores(self): self._ignoreErrors = [] class Loggable(BaseLoggable): def __init__(self, logCategory=None): if logCategory: self.logCategory = logCategory elif not hasattr(self, 'logCategory'): self.logCategory = self.__class__.__name__.lower() def logObjectName(self): res = BaseLoggable.logObjectName(self) if not res: return "<%s at 0x%x>" % (self.__class__.__name__, id(self)) return res def error(self, format, *args): if _canShortcutLogging(self.logCategory, ERROR): return doLog(ERROR, self.logObjectName(), self.logCategory, format, self.logFunction(*args), where=-2)