source: trunk/moap/util/log.py @ 40

# -*- Mode: Python -*-
# vi:si:et:sw=4:sts=4:ts=4
#
# moap - Maintenance Of A Project
# Copyright (C) 2006 Thomas Vander Stichele <thomas at apestaart dot org>

# This program is free software; you can redistribute it and/or modify
# it under the terms of the GNU General Public License as published by
# the Free Software Foundation; either version 2 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 General Public License for more details.
#
# You should have received a copy of the GNU General Public License
# along with this program; if not, write to the Free Software
# Foundation, Inc., 59 Temple Street #330, Boston, MA 02111-1307, USA.

# this file adapted from Flumotion, (C) Copyright Fluendo

"""
Logging
"""
import sys
import os
import fnmatch
import time
import traceback

# environment variables controlling levels for each category
_MOAP_DEBUG = "*:1"

# dynamic dictionary of categories already seen and their level
_categories = {}

# log handlers registered
_log_handlers = []
_log_handlers_limited = []

_initialized = False

# public log levels
ERROR = 1
WARN = 2
INFO = 3
DEBUG = 4
LOG = 5

def getLevelName(level):
    """
    Return the name of a log level.
    """
    assert isinstance(level, int) and level > 0 and level < 6, \
           "Bad debug level"
    return ('ERROR', 'WARN', 'INFO', 'DEBUG', 'LOG')[level - 1]

def registerCategory(category):
    """
    Register a given category in the debug system.
    A level will be assigned to it based on the setting of MOAP_DEBUG.
    """
    # parse what level it is set to based on MOAP_DEBUG
    # example: *:2,admin:4
    global _MOAP_DEBUG
    global _levels
    global _categories

    level = 0
    chunks = _MOAP_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 _categories.has_key(category):
        registerCategory(category)
    return _categories[category]

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 of everything before 'moap'
    '''
    i = filename.rfind('moap')
    if i != -1:
        filename = filename[i:]
    
    return filename

def _handle(level, object, category, format, args):
    def getFileLine():
        # Return a tuple of (file, line) for the first stack entry
        # outside of log.py (which would be the caller of log)
        frame = sys._getframe()
        while frame:
            co = frame.f_code
            if not co.co_filename.endswith('log.py'):
                return scrubFilename(co.co_filename), frame.f_lineno
            frame = frame.f_back
            
        return "Not found", 0

    if args:
        message = format % args
    else:
        message = format

    # first all the unlimited ones
    if _log_handlers:
        (fileName, line) = getFileLine()
        for handler in _log_handlers:
            try:
                handler(level, object, category, fileName, line, message)
            except TypeError:
                raise SystemError, "handler %r raised a TypeError" % handler

    if level > getCategoryLevel(category):
        return

    # set this a second time, just in case there weren't unlimited
    # loggers there before
    (fileName, line) = getFileLine()

    for handler in _log_handlers_limited:
        try:
            handler(level, object, category, fileName, line, message)
        except TypeError:
            raise SystemError, "handler %r raised a TypeError" % handler
    
def errorObject(object, cat, format, *args):
    """
    Log a fatal error message in the given category. \
    This will also raise a L{SystemError}.
    """
    _handle(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 SystemError(format % args)
    else:
        raise SystemError(format)

def warningObject(object, cat, format, *args):
    """
    Log a warning message in the given category.
    This is used for non-fatal problems.
    """
    _handle(WARN, object, cat, format, args)

def infoObject(object, cat, format, *args):
    """
    Log an informational message in the given category.
    """
    _handle(INFO, object, cat, format, args)

def debugObject(object, cat, format, *args):
    """
    Log a debug message in the given category.
    """
    _handle(DEBUG, object, cat, format, args)

def logObject(object, cat, format, *args):
    """
    Log a log message.  Used for debugging recurring events.
    """
    _handle(LOG, object, cat, format, args)

def error(cat, format, *args):
    errorObject(None, cat, format, *args)

def warning(cat, format, *args):
    warningObject(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)

class Loggable:
    """
    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.
    """

    logCategory = 'default'
    
    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 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 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 stderrHandler(level, object, category, file, line, message):
    """
    A log handler that writes to stdout.

    @type level:    string
    @type object:   string (or None)
    @type category: string
    @type message:  string
    """

    o = ""
    if object:
        o = '"' + object + '"'

    where = "(%s:%d)" % (file, line)

    try:
        # level   pid     object   cat      time
        # 5 + 1 + 7 + 1 + 32 + 1 + 17 + 1 + 15 == 80
        sys.stderr.write('%-5s [%5d] %-32s %-17s %-15s ' % (
            getLevelName(level), os.getpid(), o, category,
            time.strftime("%b %d %H:%M:%S")))
        sys.stderr.write('%-4s %s %s\n' % ("", message, where))

        # old: 5 + 1 + 20 + 1 + 12 + 1 + 32 + 1 + 7 == 80
        #sys.stderr.write('%-5s %-20s %-12s %-32s [%5d] %-4s %-15s %s\n' % (
        #    level, o, category, where, os.getpid(),
        #    "", time.strftime("%b %d %H:%M:%S"), message))
        sys.stderr.flush()
    except IOError:
        # happens in SIGCHLDHandler for example
        pass

def addLogHandler(func, limited=True):
    """
    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
    @type limited:  boolean
    @param limited: whether to automatically filter based on FLU_DEBUG
    """

    if not callable(func):
        raise TypeError, "func must be callable"

    if limited:
        _log_handlers_limited.append(func)
    else:
        _log_handlers.append(func)

def init():
    """
    Initialize the logging system and parse the MOAP_DEBUG environment
    variable.  Needs to be called before starting the actual application.
    """
    global _initialized

    if _initialized:
        return

    if os.environ.has_key('MOAP_DEBUG'):
        # install a log handler that uses the value of MOAP_DEBUG
        setSavonDebug(os.environ['MOAP_DEBUG'])
    addLogHandler(stderrHandler, limited=True)

    _initialized = True

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 setSavonDebug(string):
    """Set the MOAP_DEBUG string.  This controls the log output."""
    global _MOAP_DEBUG
    global _categories
    
    _MOAP_DEBUG = string
    debug('log', "MOAP_DEBUG set to %s" % _MOAP_DEBUG)

    # reparse all already registered category levels
    for category in _categories:
        registerCategory(category)

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 flumotion errors
    # for now
    if len(exception.args) == 1 and isinstance(exception.args[0], str):
        msg = ": %s" % exception.args[0]
    return "exception %(exc)s at %(filename)s:%(line)s: %(func)s()%(msg)s" % locals()