diff --git a/validate/tools/apps/gst-validate.py b/validate/tools/apps/gst-validate.py index 0ec711368e..95e4ffaeac 100644 --- a/validate/tools/apps/gst-validate.py +++ b/validate/tools/apps/gst-validate.py @@ -21,7 +21,7 @@ import subprocess import urlparse import urllib import ConfigParser -import logging +from loggable import Loggable from testdefinitions import Test, TestsManager, DEFAULT_TIMEOUT @@ -70,12 +70,13 @@ class GstValidateTest(Test): self.add_arguments(self.pipeline_desc) -class GstValidateManager(TestsManager): +class GstValidateManager(TestsManager, Loggable): name = "validate" def __init__(self): - super(GstValidateManager, self).__init__() + TestsManager.__init__(self) + Loggable.__init__(self) self._uris = [] def add_options(self, group): @@ -92,7 +93,7 @@ class GstValidateManager(TestsManager): self._add_test(name, scenario, pipe) def _check_discovering_info(self, media_info, uri=None): - logging.debug("Checking %s", media_info) + self.debug("Checking %s", media_info) config = ConfigParser.ConfigParser() f = open(media_info) config.readfp(f) @@ -110,7 +111,7 @@ class GstValidateManager(TestsManager): break self._uris.append((uri, config)) except ConfigParser.NoOptionError as e: - logging.debug("Exception: %s for %s", e, media_info) + self.debug("Exception: %s for %s", e, media_info) pass f.close() @@ -133,8 +134,8 @@ class GstValidateManager(TestsManager): return True - except subprocess.CalledProcessError: - logging.debug("Exception: %s", e) + except subprocess.CalledProcessError as e: + self.debug("Exception: %s", e) return False def _list_uris(self): @@ -148,7 +149,7 @@ class GstValidateManager(TestsManager): for path in self.options.paths: for root, dirs, files in os.walk(path): for f in files: - fpath = os.path.join(path, root,f) + fpath = os.path.join(path, root, f) if os.path.isdir(fpath) or fpath.endswith(MEDIA_INFO_EXT): continue elif fpath.endswith(STREAM_INFO): @@ -156,7 +157,7 @@ class GstValidateManager(TestsManager): else: self._discover_file(path2url(fpath), fpath) - logging.debug("Uris found: %s", self._uris) + self.debug("Uris found: %s", self._uris) return self._uris @@ -169,7 +170,7 @@ class GstValidateManager(TestsManager): return name - def _add_test(self, name, scenario, pipe): + def _add_playback_test(self, name, scenario, pipe): if self.options.mute: if "autovideosink" in pipe: pipe = pipe.replace("autovideosink", "fakesink") @@ -181,7 +182,7 @@ class GstValidateManager(TestsManager): npipe = pipe if scenario in SEEKING_REQUIERED_SCENARIO: if config.getboolean("media-info", "seekable") is False: - logging.debug("Do not run %s as %s does not support seeking", + self.debug("Do not run %s as %s does not support seeking", scenario, uri) continue @@ -193,7 +194,7 @@ class GstValidateManager(TestsManager): fname = "%s.%s" % (self._get_fname(name, scenario, config.get("file-info", "protocol")), os.path.basename(uri).replace(".", "_")) - logging.debug("Adding: %s", fname) + self.debug("Adding: %s", fname) self.tests.append(GstValidateTest(fname, self.options, @@ -203,7 +204,7 @@ class GstValidateManager(TestsManager): config) ) else: - logging.debug("Adding: %s", name) + self.debug("Adding: %s", name) self.tests.append(GstValidateTest(self._get_fname(fname, scenario), self.options, self.reporter, diff --git a/validate/tools/gst-validate-launcher.py b/validate/tools/gst-validate-launcher.py index 5ee63025e8..cf574214c7 100644 --- a/validate/tools/gst-validate-launcher.py +++ b/validate/tools/gst-validate-launcher.py @@ -18,7 +18,7 @@ # Boston, MA 02110-1301, USA. import os -import logging +import loggable from testdefinitions import _TestsLauncher, DEFAULT_QA_SAMPLE_PATH from utils import printc from optparse import OptionParser @@ -60,13 +60,7 @@ def main(): action="store_true", default=False, help="Mute playback output, which mean that we use " "a fakesink") - try: - level = getattr(logging, - os.environ["GST_VALIDATE_LAUNCHER_DEBUG"].upper(), - None) - logging.basicConfig(level=level) - except: - pass + loggable.init("GST_VALIDATE_LAUNCHER_DEBUG", True, False) tests_launcher = _TestsLauncher() tests_launcher.add_options(parser) diff --git a/validate/tools/loggable.py b/validate/tools/loggable.py new file mode 100644 index 0000000000..03cfb6afb4 --- /dev/null +++ b/validate/tools/loggable.py @@ -0,0 +1,1215 @@ +# 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: + """ + 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) diff --git a/validate/tools/reporters.py b/validate/tools/reporters.py index 6348747b3c..e37b29d527 100644 --- a/validate/tools/reporters.py +++ b/validate/tools/reporters.py @@ -22,7 +22,7 @@ import os import re import codecs -import logging +from loggable import Loggable from xml.sax import saxutils from utils import mkdir, Result, printc @@ -46,10 +46,12 @@ def escape_cdata(cdata): return xml_safe(cdata).replace(']]>', ']]>]]>