# 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 """ 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 logging.handlers import RotatingFileHandler, SysLogHandler 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 function :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 across 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 * adds a NullHandler if `streams` and `files` and `handlers` are all `None` * convenience functions to add most frequently used handlers ..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, handlers=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) :type streams: (:py:class:`io.IOBase`) or [:py:class:`io.IOBase`) or None :param files: list/tuple or single file name to log to :type files: None or (str) or [str] :param handlers: other handlers to customize and use with this logger :type handlers: None or [:py:class:`logging.Handler`] or (:py:class:`logging.Handler`) :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: streams = [] 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) if handlers is None: handlers = [] elif not isinstance(handlers, (list, tuple)): handlers = (handlers, ) for handler in handlers: formatter = ShortLevelFormatter(fmt=fmt, datefmt=datefmt) formatter.add_level(NOTICE, 'note') handler.setFormatter(formatter) handler.setLevel(self._level) self._log.addHandler(handler) if not self._log.handlers: self._log.addHandler(logging.NullHandler()) # 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 add_handler(self, *args, **kwargs): return self._log.addHandler(*args, **kwargs) def add_stream_handler(self, stream=sys.stdout, level='debug'): """ Add a stream handler to the current logger that logs to given stream. Note that the default here is stdout, not the python-default (stderr). """ handler = logging.StreamHandler(stream) handler.setLevel(self._level) self._log.addHandler(handler) def add_syslog_handler(self): """Add a handler that logs to syslog.""" handler = SysLogHandler(address='/dev/log') handler.setLevel(self._level) self._log.addHandler(handler) def add_file_handler(self, filename, mode='a', max_bytes=5*1024*1024, max_rotations=100, **kwargs): """ Add a handler that logs to given file. For convenience creates a :py:class:`logging.handlers.RotatingFileHandler` to avoid huge log files filling up the disc in case of error. :param str filename: path to file that logger should write to :param str mode: Mode with which to open log file; forwarded to handler :param int max_bytes: Max size in bytes of a log file before it is renamed to `[filename].1` and logging continues with an empty `[filename]`. :param int max_rotations: Max number of rotated files to keep :param dict kwargs: All other args (e.g. `encoding`) are forwarded to handler constructor. `maxBytes` and `backupCount` are overwritten with `max_bytes` and `max_rots`. """ kwargs['maxBytes'] = max_bytes kwargs['backupCount'] = max_rotations handler = RotatingFileHandler(filename, mode, **kwargs) handler.setLevel(self._level) self._log.addHandler(handler) 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 between -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 Used by :py:meth:`I2nLogger::log_count_if_interesting`. :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.)