#!/usr/bin/env python ############################################################################# ## ## This file is part of Taurus ## ## http://taurus-scada.org ## ## Copyright 2011 CELLS / ALBA Synchrotron, Bellaterra, Spain ## ## Taurus 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 3 of the License, or ## (at your option) any later version. ## ## Taurus 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 Taurus. If not, see . ## ############################################################################# """This module contains a set of useful logging elements based on python's :mod:`logging` system.""" __all__ = ["LogIt", "TraceIt", "DebugIt", "InfoIt", "WarnIt", "ErrorIt", "CriticalIt", "MemoryLogHandler", "LogExceptHook", "Logger", "LogFilter", "_log", "trace", "debug", "info", "warning", "error", "fatal", "critical"] __docformat__ = "restructuredtext" import os import sys import logging.handlers import weakref import warnings import traceback import inspect import threading from object import Object from wrap import wraps from excepthook import BaseExceptHook TRACE = 5 logging.addLevelName(TRACE, "TRACE") # # _srcfile is used when walking the stack to check when we've got the first # caller stack frame. # if hasattr(sys, 'frozen'): #support for py2exe _srcfile = "logging%s__init__%s" % (os.sep, __file__[-4:]) elif __file__[-4:].lower() in ['.pyc', '.pyo']: _srcfile = __file__[:-4] + '.py' else: _srcfile = __file__ _srcfile = os.path.normcase(_srcfile) # next bit filched from 1.5.2's inspect.py def currentframe(): """Return the frame object for the caller's stack frame.""" try: raise Exception except: return sys.exc_info()[2].tb_frame.f_back if hasattr(sys, '_getframe'): currentframe = lambda: sys._getframe(3) # done filching class LogIt(object): """A function designed to be a decorator of any method of a Logger subclass. The idea is to log the entrance and exit of any decorated method of a Logger subclass. Example:: from taurus.core.util.log import Logger, LogIt class Example(Logger): @LogIt(Logger.Debug) def go(self): print "Hello world " This will generate two log messages of Debug level, one before the function go is called and another when go finishes. Example output:: MainThread DEBUG 2010-11-15 15:36:11,440 Example: -> go Hello world of mine MainThread DEBUG 2010-11-15 15:36:11,441 Example: <- go This decorator can receive two optional arguments **showargs** and **showret** which are set to False by default. Enabling them will had verbose infomation about the parameters and return value. The following example:: from taurus.core.uti.log import Logger, LogIt class Example(Logger): @LogIt(Logger.Debug, showargs=True, showret=True) def go(self, msg): msg = "Hello world",msg print msg return msg would generate an output like:: MainThread DEBUG 2010-11-15 15:42:02,353 Example: -> go('of mine',) Hello world of mine MainThread DEBUG 2010-11-15 15:42:02,353 Example: <- go = Hello world of mine .. note:: it may happen that in these examples that the output of the method appears before or after the log messages. This is because log messages are, by default, written to the *stardard error* while the print message inside the go method outputs to the *standard ouput*. On many systems these two targets are not synchronized. """ def __init__(self, level=logging.DEBUG, showargs=False, showret=False, col_limit=0): self._level = level self._showargs = showargs self._showret = showret self._col_limit = col_limit def __call__(self, f): @wraps(f) def wrapper(*args, **kwargs): f_self = args[0] if f_self.log_level > self._level: return f(*args, **kwargs) has_log = hasattr(f_self, "log") fname = f.func_name log_obj = f_self if not has_log: log_obj = logging.getLogger() try: fname = "%s.%s" % (f_self.__class__.__name__, fname) except: pass in_msg = "-> %s" % fname if self._showargs: if len(args) > 1: in_msg += str(args[1:]) if len(kwargs): in_msg += str(kwargs) if self._col_limit and len(in_msg) > self._col_limit: in_msg = "%s [...]" % in_msg[:self._col_limit-6] log_obj.log(self._level, in_msg) out_msg = "<-" try: ret = f(*args, **kwargs) except Exception, e: exc_info = sys.exc_info() out_msg += " (with %s) %s" % (e.__class__.__name__, fname) log_obj.log(self._level, out_msg, exc_info=exc_info) raise out_msg += " %s" % fname if not ret is None and self._showret: out_msg += " = %s" % str(ret) if self._col_limit and len(out_msg) > self._col_limit: out_msg = "%s [...]" % out_msg[:self._col_limit-6] log_obj.log(self._level, out_msg) return ret return wrapper class TraceIt(LogIt): """Specialization of LogIt for trace level messages. Example:: from taurus.core.util.log import Logger, TraceIt class Example(Logger): @TraceIt() def go(self): print "Hello world" .. seealso:: :class:`LogIt`""" def __init__(self, showargs=False, showret=False): LogIt.__init__(self, level=TRACE, showargs=showargs, showret=showret) class DebugIt(LogIt): """Specialization of LogIt for debug level messages. Example:: from taurus.core.util.log import Logger, DebugIt class Example(Logger): @DebugIt() def go(self): print "Hello world" .. seealso:: :class:`LogIt`""" def __init__(self, showargs=False, showret=False): LogIt.__init__(self, level=logging.DEBUG, showargs=showargs, showret=showret) class InfoIt(LogIt): """Specialization of LogIt for info level messages. Example:: from taurus.core.util.log import Logger, InfoIt class Example(Logger): @InfoIt() def go(self): print "Hello world" .. seealso:: :class:`LogIt`""" def __init__(self, showargs=False, showret=False): LogIt.__init__(self, level=logging.INFO, showargs=showargs, showret=showret) class WarnIt(LogIt): """Specialization of LogIt for warn level messages. Example:: from taurus.core.util.log import Logger, WarnIt class Example(Logger): @WarnIt() def go(self): print "Hello world" .. seealso:: :class:`LogIt`""" def __init__(self, showargs=False, showret=False): LogIt.__init__(self, level=logging.WARN, showargs=showargs, showret=showret) class ErrorIt(LogIt): """Specialization of LogIt for error level messages. Example:: from taurus.core.util.log import Logger, ErrorIt class Example(Logger): @ErrorIt() def go(self): print "Hello world" .. seealso:: :class:`LogIt`""" def __init__(self, showargs=False, showret=False): LogIt.__init__(self, level=logging.ERROR, showargs=showargs, showret=showret) class CriticalIt(LogIt): """Specialization of LogIt for critical level messages. Example:: from taurus.core.util.log import Logger, CriticalIt class Example(Logger): @CriticalIt() def go(self): print "Hello world" .. seealso:: :class:`LogIt`""" def __init__(self, showargs=False, showret=False): LogIt.__init__(self, level=logging.CRITICAL, showargs=showargs, showret=showret) class MemoryLogHandler(list, logging.handlers.BufferingHandler): """An experimental log handler that stores temporary records in memory. When flushed it passes the records to another handler""" def __init__(self, capacity=1000): list.__init__(self) logging.handlers.BufferingHandler.__init__(self, capacity=capacity) self._handler_list_changed = False def shouldFlush(self, record): """Determines if the given record should trigger the flush :param record: (logging.LogRecord) a log record :return: (bool) wheter or not the handler should be flushed """ return (len(self.buffer) >= self.capacity) or \ (record.levelno >= Logger.getLogLevel()) or \ self._handler_list_changed def flush(self): """Flushes this handler""" for record in self.buffer: for handler in self: handler.handle(record) self.buffer = [] def close(self): """Closes this handler""" self.flush() del self[:] logging.handlers.BufferingHandler.close(self) class LogExceptHook(BaseExceptHook): """A callable class that acts as an excepthook that logs the exception in the python logging system. :param hook_to: callable excepthook that will be called at the end of this hook handling [default: None] :type hook_to: callable :param name: logger name [default: None meaning use class name] :type name: str :param level: log level [default: logging.ERROR] :type level: int""" def __init__(self, hook_to=None, name=None, level=logging.ERROR): BaseExceptHook.__init__(self, hook_to=hook_to) name = name or self.__class__.__name__ self._level = level self._log = Logger(name=name) def report(self, *exc_info): text = "".join(traceback.format_exception(*exc_info)) if text[-1] == '\n': text = text[:-1] self._log.log(self._level, "Unhandled exception:\n%s", text) class _Logger(logging.Logger): def findCaller(self): """ Find the stack frame of the caller so that we can note the source file name, line number and function name. """ f = currentframe() #On some versions of IronPython, currentframe() returns None if #IronPython isn't run with -X:Frames. if f is not None: f = f.f_back rv = "(unknown file)", 0, "(unknown function)" while hasattr(f, "f_code"): co = f.f_code filename = os.path.normcase(co.co_filename) if filename in (_srcfile, logging._srcfile): f = f.f_back continue rv = (co.co_filename, f.f_lineno, co.co_name) break return rv class Logger(Object): """The taurus logger class. All taurus pertinent classes should inherit directly or indirectly from this class if they need taurus logging facilities.""" #: Internal usage root_inited = False #: Internal usage root_init_lock = threading.Lock() #: Critical message level (constant) Critical = logging.CRITICAL #: Fatal message level (constant) Fatal = logging.FATAL #: Error message level (constant) Error = logging.ERROR #: Warning message level (constant) Warning = logging.WARNING #: Info message level (constant) Info = logging.INFO #: Debug message level (constant) Debug = logging.DEBUG #: Trace message level (constant) Trace = TRACE #: Default log level (constant) DftLogLevel = Info #: Default log message format (constant) DftLogMessageFormat = '%(threadName)-14s %(levelname)-8s %(asctime)s %(name)s: %(message)s' #: Default log format (constant) DftLogFormat = logging.Formatter(DftLogMessageFormat) #: Current global log level log_level = DftLogLevel #: Default log message format log_format = DftLogFormat #: the main stream handler stream_handler = None def __init__(self, name='', parent=None, format=None): """The Logger constructor :param name: (str) the logger name (default is empty string) :param parent: (Logger) the parent logger or None if no parent exists (default is None) :param format: (str) the log message format or None to use the default log format (default is None) """ self.call__init__(Object) if format: self.log_format = format Logger.initRoot() if name is None or len(name) == 0: name = self.__class__.__name__ self.log_name = name if parent is not None: self.log_full_name = '%s.%s' % (parent.log_full_name, name) else: self.log_full_name = name self.log_obj = self._getLogger(self.log_full_name) self.log_handlers = [] self.log_parent = None self.log_children = {} if parent is not None: self.log_parent = weakref.ref(parent) parent.addChild(self) def cleanUp(self): """The cleanUp. Default implementation does nothing Overwrite when necessary""" pass @classmethod def initRoot(cls): """Class method to initialize the root logger. Do **NOT** call this method directly in your code """ if cls.root_inited: return cls._getLogger() try: cls.root_init_lock.acquire() root_logger = cls._getLogger() logging.addLevelName(cls.Trace, "TRACE") cls.stream_handler = logging.StreamHandler(sys.__stderr__) cls.stream_handler.setFormatter(cls.log_format) root_logger.addHandler(cls.stream_handler) console_log_level = os.environ.get("TAURUSLOGLEVEL", None) if console_log_level is not None: console_log_level = console_log_level.capitalize() if hasattr(cls, console_log_level): cls.log_level = getattr(cls, console_log_level) root_logger.setLevel(cls.log_level) Logger.root_inited = True finally: cls.root_init_lock.release() return root_logger @classmethod def addRootLogHandler(cls, h): """Adds a new handler to the root logger :param h: (logging.Handler) the new log handler """ h.setFormatter(cls.getLogFormat()) cls.initRoot().addHandler(h) @classmethod def removeRootLogHandler(cls, h): """Removes the given handler from the root logger :param h: (logging.Handler) the handler to be removed """ cls.initRoot().removeHandler(h) @classmethod def enableLogOutput(cls): """Enables the :class:`logging.StreamHandler` which dumps log records, by default, to the stderr. """ cls.initRoot().addHandler(cls.stream_handler) @classmethod def disableLogOutput(cls): """Disables the :class:`logging.StreamHandler` which dumps log records, by default, to the stderr. """ cls.initRoot().removeHandler(cls.stream_handler) @classmethod def setLogLevel(cls,level): """sets the new log level (the root log level) :param level: (int) the new log level """ cls.log_level = level cls.initRoot().setLevel(level) @classmethod def getLogLevel(cls): """Retuns the current log level (the root log level) :return: (int) a number representing the log level """ return cls.log_level @classmethod def setLogFormat(cls,format): """sets the new log message format :param level: (str) the new log message format """ cls.log_format = logging.Formatter(format) root_logger = cls.initRoot() for h in root_logger.handlers: h.setFormatter(cls.log_format) @classmethod def getLogFormat(cls): """Retuns the current log message format (the root log format) :return: (str) the log message format """ return cls.log_format @classmethod def resetLogLevel(cls): """Resets the log level (the root log level)""" cls.setLogLevel(cls.DftLogLevel) @classmethod def resetLogFormat(cls): """Resets the log message format (the root log format)""" cls.setLogFormat(cls.DftLogFormat) @classmethod def addLevelName(cls, level_no, level_name): """Registers a new log level :param level_no: (int) the level number :param level_name: (str) the corresponding name """ logging.addLevelName(level_no, level_name) level_name = level_name.capitalize() if not hasattr(cls, level_name): setattr(cls, level_name, level_no) @classmethod def getRootLog(cls): """Retuns the root logger :return: (logging.Logger) the root logger """ return cls.initRoot() @staticmethod def _getLogger(name=None): orig_logger_class = logging.getLoggerClass() try: logging.setLoggerClass(_Logger) ret = logging.getLogger(name) return ret finally: logging.setLoggerClass(orig_logger_class) @classmethod def getLogger(cls, name=None): cls.initRoot() return cls._getLogger(name=name) def getLogObj(self): """Returns the log object for this object :return: (logging.Logger) the log object """ return self.log_obj def getParent(self): """Returns the log parent for this object or None if no parent exists :return: (logging.Logger or None) the log parent for this object """ if self.log_parent is None: return None return self.log_parent() def getChildren(self): """Returns the log children for this object :return: (sequence= 3: out += '\n\t line = [%d]: %s' % (line-1, lines[0]) out += '\n\t -> line = [%d]: %s' % (line, lines[1]) out += '\n\t line = [%d]: %s' % (line+1, lines[2]) elif line_nb > 0: out += '\n\t -> line = [%d]: %s' % (line, lines[0]) if frame: out += '\n\t locals = ' for k,v in frame.f_locals.items(): out += '\n\t\t%20s = ' % k try: cut = False v = str(v) i = v.find('\n') if i == -1: i = 80 else: i = min(i, 80) cut = True if len(v) > 80: cut = True out += v[:i] if cut: out += '[...]' except: out += '' return out def log(self, level, msg, *args, **kw): """Record a log message in this object's logger. Accepted *args* and *kwargs* are the same as :meth:`logging.Logger.log`. :param level: (int) the record level :param msg: (str) the message to be recorded :param args: list of arguments :param kw: list of keyword arguments """ self.log_obj.log(level, msg, *args, **kw) def debug(self, msg, *args, **kw): """Record a debug message in this object's logger. Accepted *args* and *kwargs* are the same as :meth:`logging.Logger.debug`. :param msg: (str) the message to be recorded :param args: list of arguments :param kw: list of keyword arguments """ self.log_obj.debug(msg, *args, **kw) def info(self, msg, *args, **kw): """Record an info message in this object's logger. Accepted *args* and *kwargs* are the same as :meth:`logging.Logger.info`. :param msg: (str) the message to be recorded :param args: list of arguments :param kw: list of keyword arguments """ self.log_obj.info(msg, *args, **kw) def warning(self, msg, *args, **kw): """Record a warning message in this object's logger. Accepted *args* and *kwargs* are the same as :meth:`logging.Logger.warning`. :param msg: (str) the message to be recorded :param args: list of arguments :param kw: list of keyword arguments """ self.log_obj.warning(msg, *args, **kw) def deprecated(self, msg, *args, **kw): """Record a deprecated warning message in this object's logger. Accepted *args* and *kwargs* are the same as :meth:`logging.Logger.warning`. :param msg: (str) the message to be recorded :param args: list of arguments :param kw: list of keyword arguments """ filename, lineno, func = self.log_obj.findCaller() depr_msg = warnings.formatwarning(msg, DeprecationWarning, filename, lineno) self.log_obj.warning(depr_msg, *args, **kw) def error(self, msg, *args, **kw): """Record an error message in this object's logger. Accepted *args* and *kwargs* are the same as :meth:`logging.Logger.error`. :param msg: (str) the message to be recorded :param args: list of arguments :param kw: list of keyword arguments """ self.log_obj.error(msg, *args, **kw) def fatal(self, msg, *args, **kw): """Record a fatal message in this object's logger. Accepted *args* and *kwargs* are the same as :meth:`logging.Logger.fatal`. :param msg: (str) the message to be recorded :param args: list of arguments :param kw: list of keyword arguments """ self.log_obj.fatal(msg, *args, **kw) def critical(self, msg, *args, **kw): """Record a critical message in this object's logger. Accepted *args* and *kwargs* are the same as :meth:`logging.Logger.critical`. :param msg: (str) the message to be recorded :param args: list of arguments :param kw: list of keyword arguments """ self.log_obj.critical(msg, *args, **kw) def exception(self, msg, *args): """Log a message with severity 'ERROR' on the root logger, with exception information.. Accepted *args* are the same as :meth:`logging.Logger.exception`. :param msg: (str) the message to be recorded :param args: list of arguments """ self.log_obj.exception(msg, *args) def flushOutput(self): """Flushes the log output""" self.syncLog() def syncLog(self): """Synchronises the log output""" logger = self synced = [] while logger is not None: for handler in logger.log_handlers: if handler in synced: continue try: sync = getattr(handler, 'sync') except: continue sync() synced.append(handler) logger = logger.getParent() def getLogName(self): """Gets the log name for this object :return: (str) the log name """ return self.log_name def getLogFullName(self): """Gets the full log name for this object :return: (str) the full log name """ return self.log_full_name def changeLogName(self,name): """Change the log name for this object. :param name: (str) the new log name """ self.log_name = name p = self.getParent() if p is not None: self.log_full_name = '%s.%s' % (p.log_full_name, name) else: self.log_full_name = name self.log_obj = logging.getLogger(self.log_full_name) for handler in self.log_handlers: self.log_obj.addHandler(handler) for child in self.getChildren(): child.changeLogName(child.log_name) class LogFilter(logging.Filter): """Experimental log filter""" def __init__(self, level): self.filter_level = level logging.Filter.__init__(self) def filter(self, record): ok = (record.levelno == self.filter_level) return ok def __getrootlogger(): return Logger.getLogger("TaurusRootLogger") # cannot export log because upper package taurus.core.util imports this 'log' # module and it would itself be overwritten by this log function def _log(level, msg, *args, **kw): return __getrootlogger().log(level, msg, *args, **kw) def trace(msg, *args, **kw): return _log(Logger.Trace, msg, *args, **kw) def debug(msg, *args, **kw): return __getrootlogger().debug(msg, *args, **kw) def info(msg, *args, **kw): return __getrootlogger().info(msg, *args, **kw) def warning(msg, *args, **kw): return __getrootlogger().warning(msg, *args, **kw) def error(msg, *args, **kw): return __getrootlogger().error(msg, *args, **kw) def fatal(msg, *args, **kw): return __getrootlogger().fatal(msg, *args, **kw) def critical(msg, *args, **kw): return __getrootlogger().critical(msg, *args, **kw)