developer.intra2net.com Git - pyi2ncommon/blob - src/log_helpers.py

   1 # The software in this package is distributed under the GNU General
   2 # Public License version 2 (with a special exception described below).
   3 #
   4 # A copy of GNU General Public License (GPL) is included in this distribution,
   5 # in the file COPYING.GPL.
   6 #
   7 # As a special exception, if other files instantiate templates or use macros
   8 # or inline functions from this file, or you compile this file and link it
   9 # with other works to produce a work based on this file, this file
  10 # does not by itself cause the resulting work to be covered
  11 # by the GNU General Public License.
  12 #
  13 # However the source code for this file must still be made available
  14 # in accordance with section (3) of the GNU General Public License.
  15 #
  16 # This exception does not invalidate any other reasons why a work based
  17 # on this file might be covered by the GNU General Public License.
  18 #
  19 # Copyright (c) 2016-2018 Intra2net AG <info@intra2net.com>
  20
  21 """ Helpers for logging; featuring:
  22
  23 ShortLevelFormatter: provide a 4-char-sized field "shortlevel" for message
  24 urgency (dbug/info/warn/err /crit)
  25
  26 I2nLogger: logger that provides a notice(), allows omission for str.format
  27            and is quite convenient in general
  28
  29 get_logger: factor for creating I2nLoggers
  30
  31 Further ideas: ::
  32 * allow milliseconds in dateformat field (see test_short_level_format)
  33 * create own basicConfig-like function that uses our classes as default
  34   --> started using I2nLogger constructor and get_logger
  35 * try to find out module that calls I2nLogger constructor to provide a good
  36   default value for name (finding out the current module is a pain in the a..)
  37
  38 .. todo:: create unittests from test_* functions at bottom
  39 .. todo:: think about how to allow different levels per handler
  40 .. todo:: do not limit logs by line numbers but by disc size? Warn when at 50%,
  41          75%, 90%, 99% of limit?
  42 """
  43
  44 import logging
  45 from logging import DEBUG, INFO, WARNING, ERROR, CRITICAL, NOTSET
  46 from math import log10, floor
  47 import sys
  48
  49 from .type_helpers import isstr
  50
  51 #: log level half-way between INFO and WARNING
  52 NOTICE = (INFO + WARNING)//2
  53 logging.addLevelName(NOTICE, 'NOTICE')
  54
  55 #: default formatting string for ShortLevelFormatter
  56 DEFAULT_SHORT_LEVEL_FORMAT = '%(asctime)s:%(msecs)03d %(shortlevel)s| %(msg)s'
  57
  58 #: default formatting string for date/time in ShortLevelFormatter
  59 DEFAULT_SHORT_LEVEL_DATE_FORMAT = '%H:%M:%S'
  60
  61 #: mapping from level name to level int for I2nLogger's set_level
  62 LEVEL_DICT = dict(notset=NOTSET, debug=DEBUG, info=INFO, notice=NOTICE,
  63                   warning=WARNING, error=ERROR, critical=CRITICAL)
  64
  65 #: min level allowed in I2nLogger
  66 MIN_LEVEL = NOTSET
  67
  68 #: max level allowed in I2nLogger
  69 MAX_LEVEL = CRITICAL
  70
  71 #: constant for I2nLogger streams argument: stream to stdout
  72 STDOUT = sys.stdout
  73
  74
  75 class ShortLevelFormatter(logging.Formatter):
  76     """
  77     Formatter for logging handlers that allows use of format field "shortlevel"
  78
  79     using this formatter, you can specify in the log message format string the
  80     field "shortlevel" which will introduce in your log messages a 4-char field
  81     for the log record urgency: "DEBUG" --> "dbug", "INFO" --> "info",
  82     "WARNING" --> "warn", "ERROR" --> "err ", "CRITICAL" --> "crit"
  83
  84     All other functionality (like other format fields) is inherited from base
  85     class Formatter
  86
  87     Most easily used indirectly through :py:class:`I2nLogger`
  88     (uses this by default)
  89
  90     Explicit usage example::
  91
  92         logger = logging.getLogger(__name__)
  93         logger.setLevel(logging.DEBUG)
  94         handler = logging.StreamHandler()
  95         handler.setLevel(logging.DEBUG)
  96         formatter = ShortLevelFormatter('%(shortlevel)s| %(msg)s')
  97         handler.setFormatter(formatter)
  98         logger.addHandler(handler)
  99
 100     You can even add new levels::
 101
 102         notice = (logging.INFO + logging.WARNING)/2
 103         formatter.add_level(notice, 'note')
 104         logger.log(notice, 'more important than info but no warning nor error')
 105
 106     .. seealso:: testing funcion :py:func:`test_short_level_format`
 107     """
 108
 109     def __init__(self, fmt=DEFAULT_SHORT_LEVEL_FORMAT,
 110                  datefmt=DEFAULT_SHORT_LEVEL_DATE_FORMAT, *args, **kwargs):
 111         """ creates a new ShortLevelFormatter
 112
 113         forwards all args to super class Formatter and initializes dict with
 114         levelno and short string representations
 115         """
 116         self.parent = super(ShortLevelFormatter, self)
 117         self.parent.__init__(fmt=fmt, datefmt=datefmt, *args, **kwargs)
 118         self._shortlevel_dict = {DEBUG: 'dbug', INFO: 'info', WARNING: 'warn',
 119                                  ERROR: 'err ', CRITICAL: 'crit',
 120                                  NOTSET: '----'}
 121
 122     def format(self, record):
 123         """ create string representation of given log record """
 124         try:
 125             record.shortlevel = self._shortlevel_dict[record.levelno]
 126         except KeyError:
 127             record.shortlevel = '????'
 128
 129         return self.parent.format(record)
 130
 131     def add_level(self, levelno, shortlevel_str):
 132         """ add a new message urgency level
 133
 134         :param int levelno: numeric urgency level
 135         :param str shortlevel_str: string representation of message urgency;
 136                                    should be of length 4
 137         :returns: nothing
 138         """
 139
 140         self._shortlevel_dict[levelno] = shortlevel_str
 141
 142
 143 #: memory for all I2nLogger instances in current session to avoid overwrite
 144 #: used in :py:func:`get_logger` and :py:class:`I2nLogger` constructor
 145 _i2n_loggers = {}
 146
 147
 148 def get_logger(name, *args, **kwargs):
 149     """ factory for :py:class:`I2nLogger`: create new or return existing object
 150
 151     all args as in :py:class:`I2nLogger` constructor; args will be ignored if
 152     logger with given name exists already!
 153     """
 154
 155     if name in _i2n_loggers:
 156         return _i2n_loggers[name]    # ignore all args
 157     else:
 158         return I2nLogger(name, *args, **kwargs)
 159
 160
 161 class I2nLogger:
 162     """ a more convenient logger
 163
 164     Features::
 165     * can be used without ".format()" as follows::
 166
 167         logger.info('the result is {0}', result)    # more convenient than...
 168         logger.info('the result is {0}'.format(result))    # ... the original
 169
 170     * Has a :py:meth:`Logger.notice` function
 171     * Has by default as only handler a :py:class:`logging.StreamHandler` to
 172       stdout with a :py:class:`ShortLevelFormatter`
 173     * Simplifies setting of logger's logging level using
 174       :py:meth:`Logger.set_level`. The level is kept in sync between logger and
 175       handlers and can be queried using :py:meth:`get_level`
 176       (does not work accross logger hierarchies!)
 177     * can specify name and level and [date]fmt all in constructor
 178     * can limit the number of lines this logger will produce to prevent filling
 179       hard drive with log file
 180       (assumes one line per call to log/debug/info/notice/...,
 181        only counts calls with priority above this logger's level)
 182     * provides shorter method names: dbg, note, warn, err
 183
 184     ..note:: Creating multiple instances with the same name is not allowed and
 185              will result in an error. Use :py:func:`get_logger` instead of this
 186              constructor to avoid such situtations
 187
 188     ..note:: Do not change or use the underlying logger or functionality here
 189              (in particular, get_level) is no longer reliable!
 190     """
 191
 192     def __init__(self, name, level=INFO, fmt=DEFAULT_SHORT_LEVEL_FORMAT,
 193                  datefmt=DEFAULT_SHORT_LEVEL_DATE_FORMAT,
 194                  streams=STDOUT, files=None, handlers=None):
 195         """ creates a I2nLogger; forwards args to logging.getLogger
 196
 197
 198         :param str name: name of this logger, best practice is module name
 199         :param int level: best use one of the constants DEBUG, INFO NOTICE,
 200                           WARNING, ERROR
 201         :param str fmt: format of log messages, see
 202                         :py:class:`ShortLevelFormatter` for more help
 203         :param str datefmt: format of date added to log messages, see
 204                             :py:class:`ShortLevelFormatter` for more help
 205         :param streams: list/tuple of or a single stream to log to, default is
 206                         STDOUT (=sys.stdout)
 207         :type streams: (:py:class:`io.IOBase`) or [:py:class:`io.IOBase`) or
 208                        None
 209         :param files: list/tuple or single file name to log to
 210         :type files: None or (str) or [str]
 211         :param handlers: other handlers to customize and use with this logger
 212         :type handlers: None or [:py:class:`logging.Handler`] or
 213                         (:py:class:`logging.Handler`)
 214         :raise: ValueError if an I2nLogger with the same name exists already
 215         """
 216
 217         # check if an instance with the same name has been created earlier
 218         # to prevent conflicts
 219         global _i2n_loggers
 220         if name in _i2n_loggers:
 221             raise ValueError("An I2nLogger with that exact name ('{0}') exists"
 222                              " already -- use get_logger instead!"
 223                              .format(name))
 224
 225         self._log = logging.getLogger(name)
 226         if isinstance(level, str):
 227             level = LEVEL_DICT[level]
 228         self._level = min(MAX_LEVEL, max(MIN_LEVEL, level))
 229         self._log.setLevel(self._level)
 230
 231         # remove handlers (sometimes there are mutliple by default)
 232         for handler in self._log.handlers:
 233             self._log.removeHandler(handler)
 234
 235         # create new handlers and formatter
 236         if streams is None:
 237             stream = []
 238         elif not isinstance(streams, (list, tuple)):
 239             streams = (streams, )
 240         for stream in streams:
 241             formatter = ShortLevelFormatter(fmt=fmt, datefmt=datefmt)
 242             formatter.add_level(NOTICE, 'note')
 243             new_handler = logging.StreamHandler(stream)
 244             new_handler.setFormatter(formatter)
 245             new_handler.setLevel(self._level)
 246             self._log.addHandler(new_handler)
 247
 248         if files is None:
 249             files = []
 250         elif not isinstance(files, (list, tuple)):
 251             files = (files, )
 252         for file_name in files:
 253             formatter = ShortLevelFormatter(fmt=fmt, datefmt=datefmt)
 254             formatter.add_level(NOTICE, 'note')
 255             new_handler = logging.FileHandler(file_name)
 256             new_handler.setFormatter(formatter)
 257             new_handler.setLevel(self._level)
 258             self._log.addHandler(new_handler)
 259
 260         if handlers is None:
 261             handlers = []
 262         elif not isinstance(handlers, (list, tuple)):
 263             handlers = (handlers, )
 264         for handler in handlers:
 265             formatter = ShortLevelFormatter(fmt=fmt, datefmt=datefmt)
 266             formatter.add_level(NOTICE, 'note')
 267             handler.setFormatter(formatter)
 268             handler.setLevel(self._level)
 269             self._log.addHandler(handler)
 270
 271         # remember that this logger is a I2nLogger
 272         _i2n_loggers[name] = self
 273
 274     def dbg(self, message, *args, **kwargs):
 275         self._log_no_test(DEBUG, message, *args, **kwargs)
 276
 277     def debug(self, message, *args, **kwargs):
 278         self._log_no_test(DEBUG, message, *args, **kwargs)
 279
 280     def info(self, message, *args, **kwargs):
 281         self._log_no_test(INFO, message, *args, **kwargs)
 282
 283     def note(self, message, *args, **kwargs):
 284         self._log_no_test(NOTICE, message, *args, **kwargs)
 285
 286     def notice(self, message, *args, **kwargs):
 287         self._log_no_test(NOTICE, message, *args, **kwargs)
 288
 289     def warn(self, message, *args, **kwargs):
 290         self._log_no_test(WARNING, message, *args, **kwargs)
 291
 292     def warning(self, message, *args, **kwargs):
 293         self._log_no_test(WARNING, message, *args, **kwargs)
 294
 295     def err(self, message, *args, **kwargs):
 296         self._log_no_test(ERROR, message, *args, **kwargs)
 297
 298     def error(self, message, *args, **kwargs):
 299         self._log_no_test(ERROR, message, *args, **kwargs)
 300
 301     def exception(self, message, *args, **kwargs):
 302         if 'exc_info' in kwargs:
 303             self._log_no_test(ERROR, message, *args, **kwargs)
 304         else:
 305             self._log_no_test(ERROR, message, *args, exc_info=True, **kwargs)
 306
 307     def critical(self, message, *args, **kwargs):
 308         self._log_no_test(CRITICAL, message, *args, **kwargs)
 309
 310     def log(self, level, message, *args, **kwargs):
 311         if isinstance(level, str):
 312             level = LEVEL_DICT[level.lower()]
 313         if level >= self._level:
 314             try:
 315                 message_formatted = message.format(*args)
 316             except (KeyError, IndexError):
 317                 message_formatted = '[LOG ARGS!] ' + message
 318             self._log.log(level, message_formatted, **kwargs)
 319
 320     def _log_no_test(self, level, message, *args, **kwargs):
 321         """ same as log() but without the isinstance test for internal use"""
 322         if level >= self._level:
 323             try:
 324                 message_formatted = message.format(*args)
 325             except (KeyError, IndexError):
 326                 message_formatted = '[LOG ARGS!] ' + message
 327             self._log.log(level, message_formatted, **kwargs)
 328
 329     def log_count_if_interesting(self, count, level=INFO, counter_name=None):
 330         """ Log value of a counter in gradually coarser intervals
 331
 332         see :py:func:`is_interesting_count` for definition of "interesting"
 333         """
 334         if is_interesting_count(count):
 335             if counter_name:
 336                 self.log(level, '{0} counter is at {1}', counter_name, count)
 337             else:
 338                 self.log(level, 'Counter is at {0}', count)
 339
 340     def get_level(self):
 341         """ return int level of this logger """
 342         return self._level
 343
 344     def get_level_str(self):
 345         """ returns :py:func:`logging.getLevelName` on :py:meth:`get_level` """
 346         return logging.getLevelName(self._level)
 347
 348     def set_level(self, new_level):
 349         """ set level given an int or a str
 350
 351         :arg new_level: int or str (str is converted to lower case)
 352         :raises: KeyError if new_level is a string that is not in
 353                  :py:data:`LEVEL_DICT`
 354         """
 355         if isstr(new_level):
 356             self._level = LEVEL_DICT[new_level.lower()]
 357         else:
 358             self._level = min(MAX_LEVEL, max(MIN_LEVEL, new_level))
 359         self._log.setLevel(self._level)
 360         for handler in self._log.handlers:
 361             handler.setLevel(self._level)
 362
 363
 364 def n_digits(number):
 365     """ returns the number of digits a number has in decimal format
 366
 367     :returns: 1 for 1...9, 2 for 10...99, 3 for 100...999, ...
 368               0 for 0 (and everything else beween -1 and 1)
 369               1 for -1...-9, 2 for -10...-99, ...
 370     """
 371     if abs(number) < 1:
 372         return 0
 373     else:
 374         return floor(log10(abs(number)))+1
 375
 376 def is_interesting_count(counter):
 377     """ return True if counter has reached an "interesting" value
 378
 379     For the counter to be "interesting" becomes ever harder. At first it is
 380     easy (returns True for 1,2,3,6,10), then becomes harder (True only for
 381     10,20,30,60,100) and harder (True for 100,200,300,600,1000) and this scheme
 382     continues on a logartihmic scale.
 383
 384     An example that will print lots in the beginning and then less and less::
 385
 386         counter = 0
 387         while not end_reached():
 388             do_something()
 389             if is_interesting_count(counter):
 390                 log('reached iteration {0}'.format(counter))
 391             counter += 1
 392
 393     Or implicitly using I2nLogger::log_count_if_interesting(counter)
 394
 395     :returns: True for a few values of counter, False most of the time
 396     """
 397
 398     return float(counter) / 10.**(n_digits(counter)-1.) in (1., 2., 3., 6.)
 399
 400 def test_short_level_format():
 401     """ quick test of :py:class:`ShortLevelFormatter` """
 402
 403     logger = logging.getLogger('logtest')
 404     logger.setLevel(DEBUG)
 405     handler = logging.StreamHandler()
 406     handler.setLevel(DEBUG)
 407     formatter = ShortLevelFormatter(
 408         '%(asctime)s:%(msecs)03d %(shortlevel)s| %(msg)s'
 409         '   [regular levelname=%(levelname)s]',
 410         datefmt='%H:%M:%S')
 411     handler.setFormatter(formatter)
 412     logger.addHandler(handler)
 413
 414     # 'application' code
 415     logger.debug('debug message')
 416     logger.info('info message')
 417     logger.warn('warn message')
 418     logger.error('error message')
 419     logger.critical('critical message')
 420     logger.log(15, 'unknown level')
 421     logger.log(NOTSET, 'level not set')
 422
 423     # add notice level
 424     notice = (logging.INFO + logging.WARNING)/2
 425     formatter.add_level(notice, 'note')
 426     logger.log(notice, 'more important than info but no warning nor error')
 427
 428     # try if exception formatting still works:
 429     try:
 430         logger.info('this is what an exception looks like:')
 431         impossible_result = 1/0
 432         logger.critical('just divided 1/0! The result is {0}'
 433                         .format(impossible_result))
 434     except ZeroDivisionError:
 435         logger.exception('1/0 still does not work!', exc_info=True)
 436
 437     # done
 438     logger.info('done testing')
 439
 440 def test_get_logger():
 441     log = get_logger('logger_test')
 442     log2 = get_logger('logger_test')
 443     print(log == log2)
 444
 445
 446 def test_line_counter():
 447     log = get_logger('logger_test', max_lines=10)
 448     for idx in range(20):
 449         for _ in range(20):
 450             log.debug('should not show nor count')
 451         print('calling log for idx {0}'.format(idx))
 452         log.info('logging with idx {0}', idx)
 453         log.log_count_if_interesting(idx)
 454
 455
 456 def test_error_in_formatting():
 457     log = get_logger('logger_test')
 458     log.warn('forgot to add argument {} and {1} and {cnf} to format string')
 459     log.warn('wrong number {} of arguments {}', 1)
 460
 461 if __name__ == '__main__':
 462     #test_short_level_format()
 463     #test_get_logger()
 464     #test_line_counter()
 465     test_error_in_formatting()