[pyi2ncommon] / src / log_helpers.py

# The software in this package is distributed under the GNU General
# Public License version 2 (with a special exception described below).
#
# A copy of GNU General Public License (GPL) is included in this distribution,
# in the file COPYING.GPL.
#
# As a special exception, if other files instantiate templates or use macros
# or inline functions from this file, or you compile this file and link it
# with other works to produce a work based on this file, this file
# does not by itself cause the resulting work to be covered
# by the GNU General Public License.
#
# However the source code for this file must still be made available
# in accordance with section (3) of the GNU General Public License.
#
# This exception does not invalidate any other reasons why a work based
# on this file might be covered by the GNU General Public License.
#
# Copyright (c) 2016-2018 Intra2net AG <info@intra2net.com>

""" Helpers for logging; featuring:

ShortLevelFormatter: provide a 4-char-sized field "shortlevel" for message
urgency (dbug/info/warn/err /crit)

I2nLogger: logger that provides a notice(), allows omission for str.format
           and is quite convenient in general

get_logger: factor for creating I2nLoggers

Further ideas: ::
* allow milliseconds in dateformat field (see test_short_level_format)
* create own basicConfig-like function that uses our classes as default
  --> started using I2nLogger constructor and get_logger
* try to find out module that calls I2nLogger constructor to provide a good
  default value for name (finding out the current module is a pain in the a..)

.. todo:: create unittests from test_* functions at bottom
.. todo:: think about how to allow different levels per handler
.. todo:: do not limit logs by line numbers but by disc size? Warn when at 50%,
         75%, 90%, 99% of limit?
"""

import logging
from logging import DEBUG, INFO, WARNING, ERROR, CRITICAL, NOTSET
from math import log10, floor
import sys

from .type_helpers import isstr

#: log level half-way between INFO and WARNING
NOTICE = (INFO + WARNING)//2
logging.addLevelName(NOTICE, 'NOTICE')

#: default formatting string for ShortLevelFormatter
DEFAULT_SHORT_LEVEL_FORMAT = '%(asctime)s:%(msecs)03d %(shortlevel)s| %(msg)s'

#: default formatting string for date/time in ShortLevelFormatter
DEFAULT_SHORT_LEVEL_DATE_FORMAT = '%H:%M:%S'

#: mapping from level name to level int for I2nLogger's set_level
LEVEL_DICT = dict(notset=NOTSET, debug=DEBUG, info=INFO, notice=NOTICE,
                  warning=WARNING, error=ERROR, critical=CRITICAL)

#: min level allowed in I2nLogger
MIN_LEVEL = NOTSET

#: max level allowed in I2nLogger
MAX_LEVEL = CRITICAL

#: constant for I2nLogger streams argument: stream to stdout
STDOUT = sys.stdout


class ShortLevelFormatter(logging.Formatter):
    """
    Formatter for logging handlers that allows use of format field "shortlevel"

    using this formatter, you can specify in the log message format string the
    field "shortlevel" which will introduce in your log messages a 4-char field
    for the log record urgency: "DEBUG" --> "dbug", "INFO" --> "info",
    "WARNING" --> "warn", "ERROR" --> "err ", "CRITICAL" --> "crit"

    All other functionality (like other format fields) is inherited from base
    class Formatter

    Most easily used indirectly through :py:class:`I2nLogger`
    (uses this by default)

    Explicit usage example::

        logger = logging.getLogger(__name__)
        logger.setLevel(logging.DEBUG)
        handler = logging.StreamHandler()
        handler.setLevel(logging.DEBUG)
        formatter = ShortLevelFormatter('%(shortlevel)s| %(msg)s')
        handler.setFormatter(formatter)
        logger.addHandler(handler)

    You can even add new levels::

        notice = (logging.INFO + logging.WARNING)/2
        formatter.add_level(notice, 'note')
        logger.log(notice, 'more important than info but no warning nor error')

    .. seealso:: testing funcion :py:func:`test_short_level_format`
    """

    def __init__(self, fmt=DEFAULT_SHORT_LEVEL_FORMAT,
                 datefmt=DEFAULT_SHORT_LEVEL_DATE_FORMAT, *args, **kwargs):
        """ creates a new ShortLevelFormatter

        forwards all args to super class Formatter and initializes dict with
        levelno and short string representations
        """
        self.parent = super(ShortLevelFormatter, self)
        self.parent.__init__(fmt=fmt, datefmt=datefmt, *args, **kwargs)
        self._shortlevel_dict = {DEBUG: 'dbug', INFO: 'info', WARNING: 'warn',
                                 ERROR: 'err ', CRITICAL: 'crit',
                                 NOTSET: '----'}

    def format(self, record):
        """ create string representation of given log record """
        try:
            record.shortlevel = self._shortlevel_dict[record.levelno]
        except KeyError:
            record.shortlevel = '????'

        return self.parent.format(record)

    def add_level(self, levelno, shortlevel_str):
        """ add a new message urgency level

        :param int levelno: numeric urgency level
        :param str shortlevel_str: string representation of message urgency;
                                   should be of length 4
        :returns: nothing
        """

        self._shortlevel_dict[levelno] = shortlevel_str


#: memory for all I2nLogger instances in current session to avoid overwrite
#: used in :py:func:`get_logger` and :py:class:`I2nLogger` constructor
_i2n_loggers = {}


def get_logger(name, *args, **kwargs):
    """ factory for :py:class:`I2nLogger`: create new or return existing object

    all args as in :py:class:`I2nLogger` constructor; args will be ignored if
    logger with given name exists already!
    """

    if name in _i2n_loggers:
        return _i2n_loggers[name]    # ignore all args
    else:
        return I2nLogger(name, *args, **kwargs)


class I2nLogger:
    """ a more convenient logger

    Features::
    * can be used without ".format()" as follows::

        logger.info('the result is {0}', result)    # more convenient than...
        logger.info('the result is {0}'.format(result))    # ... the original

    * Has a :py:meth:`Logger.notice` function
    * Has by default as only handler a :py:class:`logging.StreamHandler` to
      stdout with a :py:class:`ShortLevelFormatter`
    * Simplifies setting of logger's logging level using
      :py:meth:`Logger.set_level`. The level is kept in sync between logger and
      handlers and can be queried using :py:meth:`get_level`
      (does not work accross logger hierarchies!)
    * can specify name and level and [date]fmt all in constructor
    * can limit the number of lines this logger will produce to prevent filling
      hard drive with log file
      (assumes one line per call to log/debug/info/notice/...,
       only counts calls with priority above this logger's level)
    * provides shorter method names: dbg, note, warn, err

    ..note:: Creating multiple instances with the same name is not allowed and
             will result in an error. Use :py:func:`get_logger` instead of this
             constructor to avoid such situtations

    ..note:: Do not change or use the underlying logger or functionality here
             (in particular, get_level) is no longer reliable!
    """

    def __init__(self, name, level=INFO, fmt=DEFAULT_SHORT_LEVEL_FORMAT,
                 datefmt=DEFAULT_SHORT_LEVEL_DATE_FORMAT,
                 streams=STDOUT, files=None):
        """ creates a I2nLogger; forwards args to logging.getLogger


        :param str name: name of this logger, best practice is module name
        :param int level: best use one of the constants DEBUG, INFO NOTICE,
                          WARNING, ERROR
        :param str fmt: format of log messages, see
                        :py:class:`ShortLevelFormatter` for more help
        :param str datefmt: format of date added to log messages, see
                            :py:class:`ShortLevelFormatter` for more help
        :param streams: list/tuple of or a single stream to log to, default is
                        STDOUT (=sys.stdout)
        :param files: list/tuple or single file name to log to
        :raise: ValueError if an I2nLogger with the same name exists already
        """

        # check if an instance with the same name has been created earlier
        # to prevent conflicts
        global _i2n_loggers
        if name in _i2n_loggers:
            raise ValueError("An I2nLogger with that exact name ('{0}') exists"
                             " already -- use get_logger instead!"
                             .format(name))

        self._log = logging.getLogger(name)
        if isinstance(level, str):
            level = LEVEL_DICT[level]
        self._level = min(MAX_LEVEL, max(MIN_LEVEL, level))
        self._log.setLevel(self._level)

        # remove handlers (sometimes there are mutliple by default)
        for handler in self._log.handlers:
            self._log.removeHandler(handler)

        # create new handlers and formatter
        if streams is None:
            stream = []
        elif not isinstance(streams, (list, tuple)):
            streams = (streams, )
        for stream in streams:
            formatter = ShortLevelFormatter(fmt=fmt, datefmt=datefmt)
            formatter.add_level(NOTICE, 'note')
            new_handler = logging.StreamHandler(stream)
            new_handler.setFormatter(formatter)
            new_handler.setLevel(self._level)
            self._log.addHandler(new_handler)

        if files is None:
            files = []
        elif not isinstance(files, (list, tuple)):
            files = (files, )
        for file_name in files:
            formatter = ShortLevelFormatter(fmt=fmt, datefmt=datefmt)
            formatter.add_level(NOTICE, 'note')
            new_handler = logging.FileHandler(file_name)
            new_handler.setFormatter(formatter)
            new_handler.setLevel(self._level)
            self._log.addHandler(new_handler)

        # remember that this logger is a I2nLogger
        _i2n_loggers[name] = self

    def dbg(self, message, *args, **kwargs):
        self._log_no_test(DEBUG, message, *args, **kwargs)

    def debug(self, message, *args, **kwargs):
        self._log_no_test(DEBUG, message, *args, **kwargs)

    def info(self, message, *args, **kwargs):
        self._log_no_test(INFO, message, *args, **kwargs)

    def note(self, message, *args, **kwargs):
        self._log_no_test(NOTICE, message, *args, **kwargs)

    def notice(self, message, *args, **kwargs):
        self._log_no_test(NOTICE, message, *args, **kwargs)

    def warn(self, message, *args, **kwargs):
        self._log_no_test(WARNING, message, *args, **kwargs)

    def warning(self, message, *args, **kwargs):
        self._log_no_test(WARNING, message, *args, **kwargs)

    def err(self, message, *args, **kwargs):
        self._log_no_test(ERROR, message, *args, **kwargs)

    def error(self, message, *args, **kwargs):
        self._log_no_test(ERROR, message, *args, **kwargs)

    def exception(self, message, *args, **kwargs):
        if 'exc_info' in kwargs:
            self._log_no_test(ERROR, message, *args, **kwargs)
        else:
            self._log_no_test(ERROR, message, *args, exc_info=True, **kwargs)

    def critical(self, message, *args, **kwargs):
        self._log_no_test(CRITICAL, message, *args, **kwargs)

    def log(self, level, message, *args, **kwargs):
        if isinstance(level, str):
            level = LEVEL_DICT[level.lower()]
        if level >= self._level:
            try:
                message_formatted = message.format(*args)
            except (KeyError, IndexError):
                message_formatted = '[LOG ARGS!] ' + message
            self._log.log(level, message_formatted, **kwargs)

    def _log_no_test(self, level, message, *args, **kwargs):
        """ same as log() but without the isinstance test for internal use"""
        if level >= self._level:
            try:
                message_formatted = message.format(*args)
            except (KeyError, IndexError):
                message_formatted = '[LOG ARGS!] ' + message
            self._log.log(level, message_formatted, **kwargs)

    def log_count_if_interesting(self, count, level=INFO, counter_name=None):
        """ Log value of a counter in gradually coarser intervals

        see :py:func:`is_interesting_count` for definition of "interesting"
        """
        if is_interesting_count(count):
            if counter_name:
                self.log(level, '{0} counter is at {1}', counter_name, count)
            else:
                self.log(level, 'Counter is at {0}', count)

    def get_level(self):
        """ return int level of this logger """
        return self._level

    def get_level_str(self):
        """ returns :py:func:`logging.getLevelName` on :py:meth:`get_level` """
        return logging.getLevelName(self._level)

    def set_level(self, new_level):
        """ set level given an int or a str

        :arg new_level: int or str (str is converted to lower case)
        :raises: KeyError if new_level is a string that is not in
                 :py:data:`LEVEL_DICT`
        """
        if isstr(new_level):
            self._level = LEVEL_DICT[new_level.lower()]
        else:
            self._level = min(MAX_LEVEL, max(MIN_LEVEL, new_level))
        self._log.setLevel(self._level)
        for handler in self._log.handlers:
            handler.setLevel(self._level)


def n_digits(number):
    """ returns the number of digits a number has in decimal format

    :returns: 1 for 1...9, 2 for 10...99, 3 for 100...999, ...
              0 for 0 (and everything else beween -1 and 1)
              1 for -1...-9, 2 for -10...-99, ...
    """
    if abs(number) < 1:
        return 0
    else:
        return floor(log10(abs(number)))+1

def is_interesting_count(counter):
    """ return True if counter has reached an "interesting" value

    For the counter to be "interesting" becomes ever harder. At first it is
    easy (returns True for 1,2,3,6,10), then becomes harder (True only for
    10,20,30,60,100) and harder (True for 100,200,300,600,1000) and this scheme
    continues on a logartihmic scale.

    An example that will print lots in the beginning and then less and less::

        counter = 0
        while not end_reached():
            do_something()
            if is_interesting_count(counter):
                log('reached iteration {0}'.format(counter))
            counter += 1

    Or implicitly using I2nLogger::log_count_if_interesting(counter)

    :returns: True for a few values of counter, False most of the time
    """

    return float(counter) / 10.**(n_digits(counter)-1.) in (1., 2., 3., 6.)

def test_short_level_format():
    """ quick test of :py:class:`ShortLevelFormatter` """

    logger = logging.getLogger('logtest')
    logger.setLevel(DEBUG)
    handler = logging.StreamHandler()
    handler.setLevel(DEBUG)
    formatter = ShortLevelFormatter(
        '%(asctime)s:%(msecs)03d %(shortlevel)s| %(msg)s'
        '   [regular levelname=%(levelname)s]',
        datefmt='%H:%M:%S')
    handler.setFormatter(formatter)
    logger.addHandler(handler)

    # 'application' code
    logger.debug('debug message')
    logger.info('info message')
    logger.warn('warn message')
    logger.error('error message')
    logger.critical('critical message')
    logger.log(15, 'unknown level')
    logger.log(NOTSET, 'level not set')

    # add notice level
    notice = (logging.INFO + logging.WARNING)/2
    formatter.add_level(notice, 'note')
    logger.log(notice, 'more important than info but no warning nor error')

    # try if exception formatting still works:
    try:
        logger.info('this is what an exception looks like:')
        impossible_result = 1/0
        logger.critical('just divided 1/0! The result is {0}'
                        .format(impossible_result))
    except ZeroDivisionError:
        logger.exception('1/0 still does not work!', exc_info=True)

    # done
    logger.info('done testing')

def test_get_logger():
    log = get_logger('logger_test')
    log2 = get_logger('logger_test')
    print(log == log2)


def test_line_counter():
    log = get_logger('logger_test', max_lines=10)
    for idx in range(20):
        for _ in range(20):
            log.debug('should not show nor count')
        print('calling log for idx {0}'.format(idx))
        log.info('logging with idx {0}', idx)
        log.log_count_if_interesting(idx)


def test_error_in_formatting():
    log = get_logger('logger_test')
    log.warn('forgot to add argument {} and {1} and {cnf} to format string')
    log.warn('wrong number {} of arguments {}', 1)

if __name__ == '__main__':
    #test_short_level_format()
    #test_get_logger()
    #test_line_counter()
    test_error_in_formatting()