Source code for reproman.log

# ex: set sts=4 ts=4 sw=4 noet:
# ## ### ### ### ### ### ### ### ### ### ### ### ### ### ### ### ### ### ### ##
#
#   See COPYING file distributed along with the reproman package for the
#   copyright and license terms.
#
# ## ### ### ### ### ### ### ### ### ### ### ### ### ### ### ### ### ### ### ##

import logging
import os
import sys
import platform
import logging.handlers

from os.path import basename, dirname

from .utils import is_interactive

__all__ = ['ColorFormatter']

# Snippets from traceback borrowed from duecredit which was borrowed from
# PyMVPA upstream/2.4.0-39-g69ad545  MIT license (the same copyright as DataLad)
# and then from DataLad 0.2.3-427-g09ee8d7 (MIT license, copyright notice in
# COPYING of reproman)


def mbasename(s):
    """Custom function to include directory name if filename is too common

    Also strip .py at the end
    """
    base = basename(s)
    if base.endswith('.py'):
        base = base[:-3]
    if base in set(['base', '__init__']):
        base = basename(dirname(s)) + '.' + base
    return base


class TraceBack(object):
    """Customized traceback to be included in debug messages
    """

    def __init__(self, collide=False):
        """Initialize TraceBack metric

        Parameters
        ----------
        collide : bool
          if True then prefix common with previous invocation gets
          replaced with ...
        """
        self.__prev = ""
        self.__collide = collide

        # delayed imports and preparing the regex substitution
        if collide:
            import re
            self.__prefix_re = re.compile('>[^>]*$')
        else:
            self.__prefix_re = None

        import traceback
        self._extract_stack = traceback.extract_stack

    def __call__(self):
        ftb = self._extract_stack(limit=100)[:-2]
        entries = [[mbasename(x[0]), str(x[1])] for x in ftb if mbasename(x[0]) != 'logging.__init__']
        entries = [e for e in entries if e[0] != 'unittest']

        # lets make it more consize
        entries_out = [entries[0]]
        for entry in entries[1:]:
            if entry[0] == entries_out[-1][0]:
                entries_out[-1][1] += ',%s' % entry[1]
            else:
                entries_out.append(entry)
        sftb = '>'.join(['%s:%s' % (mbasename(x[0]),
                                    x[1]) for x in entries_out])
        if self.__collide:
            # lets remove part which is common with previous invocation
            prev_next = sftb
            common_prefix = os.path.commonprefix((self.__prev, sftb))
            common_prefix2 = self.__prefix_re.sub('', common_prefix)

            if common_prefix2 != "":
                sftb = '...' + sftb[len(common_prefix2):]
            self.__prev = prev_next

        return sftb


# Recipe from http://stackoverflow.com/questions/384076/how-can-i-color-python-logging-output
# by Brandon Thomson
# Adjusted for automagic determination either coloring is needed and
# prefixing of multiline log lines
[docs]class ColorFormatter(logging.Formatter): BLACK, RED, GREEN, YELLOW, BLUE, MAGENTA, CYAN, WHITE = range(8) RESET_SEQ = "\033[0m" COLOR_SEQ = "\033[1;%dm" BOLD_SEQ = "\033[1m" COLORS = { 'WARNING': YELLOW, 'INFO': WHITE, 'DEBUG': BLUE, 'CRITICAL': YELLOW, 'ERROR': RED } def __init__(self, use_color=None, log_name=False, log_pid=False): if use_color is None: # if 'auto' - use color only if all streams are tty use_color = is_interactive() self.use_color = use_color and platform.system() != 'Windows' # don't use color on windows msg = self.formatter_msg(self._get_format(log_name, log_pid), self.use_color) self._tb = TraceBack(collide=os.environ.get('REPROMAN_LOGTRACEBACK', '') == 'collide') \ if os.environ.get('REPROMAN_LOGTRACEBACK', False) else None logging.Formatter.__init__(self, msg) def _get_format(self, log_name=False, log_pid=False): # TODO: config log.timestamp=True return (("" if not int(os.environ.get("REPROMAN_LOG_TIMESTAMP", True)) else "$BOLD%(asctime)-15s$RESET ") + ("%(name)-15s " if log_name else "") + ("{%(process)d}" if log_pid else "") + "[%(levelname)s] " "%(message)s " # "($BOLD%(filename)s$RESET:%(lineno)d)" )
[docs] def formatter_msg(self, fmt, use_color=False): if use_color: fmt = fmt.replace("$RESET", self.RESET_SEQ).replace("$BOLD", self.BOLD_SEQ) else: fmt = fmt.replace("$RESET", "").replace("$BOLD", "") return fmt
[docs] def format(self, record): if record.msg.startswith('| '): # If we already log smth which supposed to go without formatting, like # output for running a command, just return the message and be done return record.msg levelname = record.levelname if self.use_color and levelname in self.COLORS: fore_color = 30 + self.COLORS[levelname] levelname_color = self.COLOR_SEQ % fore_color + "%-7s" % levelname + self.RESET_SEQ record.levelname = levelname_color record.msg = record.msg.replace("\n", "\n| ") if self._tb: record.msg = self._tb() + " " + record.msg try: return logging.Formatter.format(self, record) except: import pdb; pdb.set_trace()
class LoggerHelper(object): """Helper to establish and control a Logger""" def __init__(self, name='reproman', logtarget=None): """ Parameters ---------- name : logtarget : string, optional If we want to use our logger for other log targets, while having a uniform control over them """ self.name = name self.logtarget = logtarget self.lgr = logging.getLogger(logtarget if logtarget is not None else name) # Prevent double logging (reprozip logs at the root level). self.lgr.propagate = False def _get_environ(self, var, default=None): return os.environ.get(self.name.upper() + '_%s' % var.upper(), default) def set_level(self, level=None, default='INFO'): """Helper to set loglevel for an arbitrary logger By default operates for 'reproman'. TODO: deduce name from upper module name so it could be reused without changes """ if level is None: # see if nothing in the environment level = self._get_environ('LOGLEVEL') if level is None: level = default try: # it might be a string which still represents an int log_level = int(level) except ValueError: # or a string which corresponds to a constant;) log_level = getattr(logging, level.upper()) self.lgr.setLevel(log_level) def get_initialized_logger(self, logtarget=None): """Initialize and return the logger Parameters ---------- target: string, optional Which log target to request logger for logtarget: { 'stdout', 'stderr', str }, optional Where to direct the logs. stdout and stderr stand for standard streams. Any other string is considered a filename. Multiple entries could be specified comma-separated Returns ------- logging.Logger """ # By default mimic previously talkative behavior logtarget = self._get_environ('LOGTARGET', logtarget or 'stderr') # Allow for multiple handlers being specified, comma-separated if ',' in logtarget: for handler_ in logtarget.split(','): self.get_initialized_logger(logtarget=handler_) return self.lgr if logtarget.lower() in ('stdout', 'stderr'): loghandler = logging.StreamHandler(getattr(sys, logtarget.lower())) use_color = is_interactive() # explicitly decide here else: # must be a simple filename # Use RotatingFileHandler for possible future parametrization to keep # log succinct and rotating loghandler = logging.handlers.RotatingFileHandler(logtarget) use_color = False # I had decided not to guard this call and just raise exception to go # out happen that specified file location is not writable etc. # But now improve with colors and useful information such as time loghandler.setFormatter( ColorFormatter(use_color=use_color, # TODO: config log.name, pid log_name=self._get_environ("LOGNAME", False), log_pid=self._get_environ("LOGPID", False), )) # logging.Formatter('%(asctime)-15s %(levelname)-6s %(message)s')) self.lgr.addHandler(loghandler) self.set_level() # set default logging level return self.lgr lgr = LoggerHelper().get_initialized_logger()