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 logging.handlers import RotatingFileHandler
  47 from math import log10, floor
  48 import sys
  49
  50 from .type_helpers import isstr
  51
  52 #: log level half-way between INFO and WARNING
  53 NOTICE = (INFO + WARNING)//2
  54 logging.addLevelName(NOTICE, 'NOTICE')
  55
  56 #: default formatting string for ShortLevelFormatter
  57 DEFAULT_SHORT_LEVEL_FORMAT = '%(asctime)s:%(msecs)03d %(shortlevel)s| %(msg)s'
  58
  59 #: default formatting string for date/time in ShortLevelFormatter
  60 DEFAULT_SHORT_LEVEL_DATE_FORMAT = '%H:%M:%S'
  61
  62 #: mapping from level name to level int for I2nLogger's set_level
  63 LEVEL_DICT = dict(notset=NOTSET, debug=DEBUG, info=INFO, notice=NOTICE,
  64                   warning=WARNING, error=ERROR, critical=CRITICAL)
  65
  66 #: min level allowed in I2nLogger
  67 MIN_LEVEL = NOTSET
  68
  69 #: max level allowed in I2nLogger
  70 MAX_LEVEL = CRITICAL
  71
  72 #: constant for I2nLogger streams argument: stream to stdout
  73 STDOUT = sys.stdout
  74
  75
  76 class ShortLevelFormatter(logging.Formatter):
  77     """
  78     Formatter for logging handlers that allows use of format field "shortlevel"
  79
  80     using this formatter, you can specify in the log message format string the
  81     field "shortlevel" which will introduce in your log messages a 4-char field
  82     for the log record urgency: "DEBUG" --> "dbug", "INFO" --> "info",
  83     "WARNING" --> "warn", "ERROR" --> "err ", "CRITICAL" --> "crit"
  84
  85     All other functionality (like other format fields) is inherited from base
  86     class Formatter
  87
  88     Most easily used indirectly through :py:class:`I2nLogger`
  89     (uses this by default)
  90
  91     Explicit usage example::
  92
  93         logger = logging.getLogger(__name__)
  94         logger.setLevel(logging.DEBUG)
  95         handler = logging.StreamHandler()
  96         handler.setLevel(logging.DEBUG)
  97         formatter = ShortLevelFormatter('%(shortlevel)s| %(msg)s')
  98         handler.setFormatter(formatter)
  99         logger.addHandler(handler)
 100
 101     You can even add new levels::
 102
 103         notice = (logging.INFO + logging.WARNING)/2
 104         formatter.add_level(notice, 'note')
 105         logger.log(notice, 'more important than info but no warning nor error')
 106
 107     .. seealso:: testing funcion :py:func:`test_short_level_format`
 108     """
 109
 110     def __init__(self, fmt=DEFAULT_SHORT_LEVEL_FORMAT,
 111                  datefmt=DEFAULT_SHORT_LEVEL_DATE_FORMAT, *args, **kwargs):
 112         """ creates a new ShortLevelFormatter
 113
 114         forwards all args to super class Formatter and initializes dict with
 115         levelno and short string representations
 116         """
 117         self.parent = super(ShortLevelFormatter, self)
 118         self.parent.__init__(fmt=fmt, datefmt=datefmt, *args, **kwargs)
 119         self._shortlevel_dict = {DEBUG: 'dbug', INFO: 'info', WARNING: 'warn',
 120                                  ERROR: 'err ', CRITICAL: 'crit',
 121                                  NOTSET: '----'}
 122
 123     def format(self, record):
 124         """ create string representation of given log record """
 125         try:
 126             record.shortlevel = self._shortlevel_dict[record.levelno]
 127         except KeyError:
 128             record.shortlevel = '????'
 129
 130         return self.parent.format(record)
 131
 132     def add_level(self, levelno, shortlevel_str):
 133         """ add a new message urgency level
 134
 135         :param int levelno: numeric urgency level
 136         :param str shortlevel_str: string representation of message urgency;
 137                                    should be of length 4
 138         :returns: nothing
 139         """
 140
 141         self._shortlevel_dict[levelno] = shortlevel_str
 142
 143
 144 #: memory for all I2nLogger instances in current session to avoid overwrite
 145 #: used in :py:func:`get_logger` and :py:class:`I2nLogger` constructor
 146 _i2n_loggers = {}
 147
 148
 149 def get_logger(name, *args, **kwargs):
 150     """ factory for :py:class:`I2nLogger`: create new or return existing object
 151
 152     all args as in :py:class:`I2nLogger` constructor; args will be ignored if
 153     logger with given name exists already!
 154     """
 155
 156     if name in _i2n_loggers:
 157         return _i2n_loggers[name]    # ignore all args
 158     else:
 159         return I2nLogger(name, *args, **kwargs)
 160
 161
 162 class I2nLogger:
 163     """ a more convenient logger
 164
 165     Features::
 166     * can be used without ".format()" as follows::
 167
 168         logger.info('the result is {0}', result)    # more convenient than...
 169         logger.info('the result is {0}'.format(result))    # ... the original
 170
 171     * Has a :py:meth:`Logger.notice` function
 172     * Has by default as only handler a :py:class:`logging.StreamHandler` to
 173       stdout with a :py:class:`ShortLevelFormatter`
 174     * Simplifies setting of logger's logging level using
 175       :py:meth:`Logger.set_level`. The level is kept in sync between logger and
 176       handlers and can be queried using :py:meth:`get_level`
 177       (does not work accross logger hierarchies!)
 178     * can specify name and level and [date]fmt all in constructor
 179     * can limit the number of lines this logger will produce to prevent filling
 180       hard drive with log file
 181       (assumes one line per call to log/debug/info/notice/...,
 182        only counts calls with priority above this logger's level)
 183     * provides shorter method names: dbg, note, warn, err
 184     * adds a NullHandler if `streams` and `files` and `handlers` are all `None`
 185     * convenience functions to add most frequently used handlers
 186
 187     ..note:: Creating multiple instances with the same name is not allowed and
 188              will result in an error. Use :py:func:`get_logger` instead of this
 189              constructor to avoid such situtations
 190
 191     ..note:: Do not change or use the underlying logger or functionality here
 192              (in particular, get_level) is no longer reliable!
 193     """
 194
 195     def __init__(self, name, level=INFO, fmt=DEFAULT_SHORT_LEVEL_FORMAT,
 196                  datefmt=DEFAULT_SHORT_LEVEL_DATE_FORMAT,
 197                  streams=STDOUT, files=None, handlers=None):
 198         """ creates a I2nLogger; forwards args to logging.getLogger
 199
 200
 201         :param str name: name of this logger, best practice is module name
 202         :param int level: best use one of the constants DEBUG, INFO NOTICE,
 203                           WARNING, ERROR
 204         :param str fmt: format of log messages, see
 205                         :py:class:`ShortLevelFormatter` for more help
 206         :param str datefmt: format of date added to log messages, see
 207                             :py:class:`ShortLevelFormatter` for more help
 208         :param streams: list/tuple of or a single stream to log to, default is
 209                         STDOUT (=sys.stdout)
 210         :type streams: (:py:class:`io.IOBase`) or [:py:class:`io.IOBase`) or
 211                        None
 212         :param files: list/tuple or single file name to log to
 213         :type files: None or (str) or [str]
 214         :param handlers: other handlers to customize and use with this logger
 215         :type handlers: None or [:py:class:`logging.Handler`] or
 216                         (:py:class:`logging.Handler`)
 217         :raise: ValueError if an I2nLogger with the same name exists already
 218         """
 219
 220         # check if an instance with the same name has been created earlier
 221         # to prevent conflicts
 222         global _i2n_loggers
 223         if name in _i2n_loggers:
 224             raise ValueError("An I2nLogger with that exact name ('{0}') exists"
 225                              " already -- use get_logger instead!"
 226                              .format(name))
 227
 228         self._log = logging.getLogger(name)
 229         if isinstance(level, str):
 230             level = LEVEL_DICT[level]
 231         self._level = min(MAX_LEVEL, max(MIN_LEVEL, level))
 232         self._log.setLevel(self._level)
 233
 234         # remove handlers (sometimes there are mutliple by default)
 235         for handler in self._log.handlers:
 236             self._log.removeHandler(handler)
 237
 238         # create new handlers and formatter
 239         if streams is None:
 240             streams = []
 241         elif not isinstance(streams, (list, tuple)):
 242             streams = (streams, )
 243         for stream in streams:
 244             formatter = ShortLevelFormatter(fmt=fmt, datefmt=datefmt)
 245             formatter.add_level(NOTICE, 'note')
 246             new_handler = logging.StreamHandler(stream)
 247             new_handler.setFormatter(formatter)
 248             new_handler.setLevel(self._level)
 249             self._log.addHandler(new_handler)
 250
 251         if files is None:
 252             files = []
 253         elif not isinstance(files, (list, tuple)):
 254             files = (files, )
 255         for file_name in files:
 256             formatter = ShortLevelFormatter(fmt=fmt, datefmt=datefmt)
 257             formatter.add_level(NOTICE, 'note')
 258             new_handler = logging.FileHandler(file_name)
 259             new_handler.setFormatter(formatter)
 260             new_handler.setLevel(self._level)
 261             self._log.addHandler(new_handler)
 262
 263         if handlers is None:
 264             handlers = []
 265         elif not isinstance(handlers, (list, tuple)):
 266             handlers = (handlers, )
 267         for handler in handlers:
 268             formatter = ShortLevelFormatter(fmt=fmt, datefmt=datefmt)
 269             formatter.add_level(NOTICE, 'note')
 270             handler.setFormatter(formatter)
 271             handler.setLevel(self._level)
 272             self._log.addHandler(handler)
 273
 274         if not self._log.handlers:
 275             self._log.addHandler(logging.NullHandler())
 276
 277         # remember that this logger is a I2nLogger
 278         _i2n_loggers[name] = self
 279
 280     def dbg(self, message, *args, **kwargs):
 281         self._log_no_test(DEBUG, message, *args, **kwargs)
 282
 283     def debug(self, message, *args, **kwargs):
 284         self._log_no_test(DEBUG, message, *args, **kwargs)
 285
 286     def info(self, message, *args, **kwargs):
 287         self._log_no_test(INFO, message, *args, **kwargs)
 288
 289     def note(self, message, *args, **kwargs):
 290         self._log_no_test(NOTICE, message, *args, **kwargs)
 291
 292     def notice(self, message, *args, **kwargs):
 293         self._log_no_test(NOTICE, message, *args, **kwargs)
 294
 295     def warn(self, message, *args, **kwargs):
 296         self._log_no_test(WARNING, message, *args, **kwargs)
 297
 298     def warning(self, message, *args, **kwargs):
 299         self._log_no_test(WARNING, message, *args, **kwargs)
 300
 301     def err(self, message, *args, **kwargs):
 302         self._log_no_test(ERROR, message, *args, **kwargs)
 303
 304     def error(self, message, *args, **kwargs):
 305         self._log_no_test(ERROR, message, *args, **kwargs)
 306
 307     def exception(self, message, *args, **kwargs):
 308         if 'exc_info' in kwargs:
 309             self._log_no_test(ERROR, message, *args, **kwargs)
 310         else:
 311             self._log_no_test(ERROR, message, *args, exc_info=True, **kwargs)
 312
 313     def critical(self, message, *args, **kwargs):
 314         self._log_no_test(CRITICAL, message, *args, **kwargs)
 315
 316     def log(self, level, message, *args, **kwargs):
 317         if isinstance(level, str):
 318             level = LEVEL_DICT[level.lower()]
 319         if level >= self._level:
 320             try:
 321                 message_formatted = message.format(*args)
 322             except (KeyError, IndexError):
 323                 message_formatted = '[LOG ARGS!] ' + message
 324             self._log.log(level, message_formatted, **kwargs)
 325
 326     def _log_no_test(self, level, message, *args, **kwargs):
 327         """ same as log() but without the isinstance test for internal use"""
 328         if level >= self._level:
 329             try:
 330                 message_formatted = message.format(*args)
 331             except (KeyError, IndexError):
 332                 message_formatted = '[LOG ARGS!] ' + message
 333             self._log.log(level, message_formatted, **kwargs)
 334
 335     def log_count_if_interesting(self, count, level=INFO, counter_name=None):
 336         """ Log value of a counter in gradually coarser intervals
 337
 338         see :py:func:`is_interesting_count` for definition of "interesting"
 339         """
 340         if is_interesting_count(count):
 341             if counter_name:
 342                 self.log(level, '{0} counter is at {1}', counter_name, count)
 343             else:
 344                 self.log(level, 'Counter is at {0}', count)
 345
 346     def get_level(self):
 347         """ return int level of this logger """
 348         return self._level
 349
 350     def get_level_str(self):
 351         """ returns :py:func:`logging.getLevelName` on :py:meth:`get_level` """
 352         return logging.getLevelName(self._level)
 353
 354     def set_level(self, new_level):
 355         """ set level given an int or a str
 356
 357         :arg new_level: int or str (str is converted to lower case)
 358         :raises: KeyError if new_level is a string that is not in
 359                  :py:data:`LEVEL_DICT`
 360         """
 361         if isstr(new_level):
 362             self._level = LEVEL_DICT[new_level.lower()]
 363         else:
 364             self._level = min(MAX_LEVEL, max(MIN_LEVEL, new_level))
 365         self._log.setLevel(self._level)
 366         for handler in self._log.handlers:
 367             handler.setLevel(self._level)
 368
 369     def add_handler(self, *args, **kwargs):
 370         return self._log.addHandler(*args, **kwargs)
 371
 372     def add_stream_handler(self, stream=sys.stdout, level='debug'):
 373         """
 374         Add a stream handler to the current logger that logs to given stream.
 375
 376         Note that the default here is stdout, not the python-default (stderr).
 377         """
 378         handler = logging.StreamHandler(stream)
 379         handler.setLevel(self._level)
 380         self._log.addHandler(handler)
 381
 382     def add_syslog_handler(self):
 383         """Add a handler that logs to syslog."""
 384         handler = SysLogHandler(address='/dev/log')
 385         handler.setLevel(self._level)
 386         self._log.addHandler(handler)
 387
 388     def add_file_handler(self, filename, mode='a', max_bytes=5*1024*1024,
 389                          max_rotations=100, **kwargs):
 390         """
 391         Add a handler that logs to given file.
 392
 393         For convenience creates a
 394         :py:class:`logging.handlers.RotatingFileHandler` to avoid huge log
 395         files filling up the disc in case of error.
 396
 397         :param str mode: Mode with which to open log file; forwarded to handler
 398         :param int max_bytes: Max size in bytes of a log file before it is
 399                               renamed to `[filename].1` and logging continues
 400                               with an empty `[filename]`.
 401         :param int max_rots: Max number of rotated files to keep
 402         :param dict kwargs: All other args (e.g. `encoding`) are forwarded to
 403                             handler constructor. `maxBytes` and `backupCount`
 404                             are overwritten with `max_bytes` and `max_rots`.
 405         """
 406         kwargs['maxBytes'] = max_bytes
 407         kwargs['backupCount'] = max_rotations
 408         handler = RotatingFileHandler(filename, mode, **kwargs)
 409         handler.setLevel(self._level)
 410         self._log.addHandler(handler)
 411
 412
 413 def n_digits(number):
 414     """ returns the number of digits a number has in decimal format
 415
 416     :returns: 1 for 1...9, 2 for 10...99, 3 for 100...999, ...
 417               0 for 0 (and everything else beween -1 and 1)
 418               1 for -1...-9, 2 for -10...-99, ...
 419     """
 420     if abs(number) < 1:
 421         return 0
 422     else:
 423         return floor(log10(abs(number)))+1
 424
 425 def is_interesting_count(counter):
 426     """ return True if counter has reached an "interesting" value
 427
 428     For the counter to be "interesting" becomes ever harder. At first it is
 429     easy (returns True for 1,2,3,6,10), then becomes harder (True only for
 430     10,20,30,60,100) and harder (True for 100,200,300,600,1000) and this scheme
 431     continues on a logartihmic scale.
 432
 433     An example that will print lots in the beginning and then less and less::
 434
 435         counter = 0
 436         while not end_reached():
 437             do_something()
 438             if is_interesting_count(counter):
 439                 log('reached iteration {0}'.format(counter))
 440             counter += 1
 441
 442     Or implicitly using I2nLogger::log_count_if_interesting(counter)
 443
 444     :returns: True for a few values of counter, False most of the time
 445     """
 446
 447     return float(counter) / 10.**(n_digits(counter)-1.) in (1., 2., 3., 6.)