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, SysLogHandler
  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 function :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     """
 164     A more convenient logger
 165
 166     Features::
 167     * can be used without ".format()" as follows::
 168
 169         logger.info('the result is {0}', result)    # more convenient than...
 170         logger.info('the result is {0}'.format(result))    # ... the original
 171
 172     * Has a :py:meth:`Logger.notice` function
 173     * Has by default as only handler a :py:class:`logging.StreamHandler` to
 174       stdout with a :py:class:`ShortLevelFormatter`
 175     * Simplifies setting of logger's logging level using
 176       :py:meth:`Logger.set_level`. The level is kept in sync between logger and
 177       handlers and can be queried using :py:meth:`get_level`
 178       (does not work across logger hierarchies!)
 179     * can specify name and level and [date]fmt all in constructor
 180     * can limit the number of lines this logger will produce to prevent filling
 181       hard drive with log file
 182       (assumes one line per call to log/debug/info/notice/...,
 183       only counts calls with priority above this logger's level)
 184     * provides shorter method names: dbg, note, warn, err
 185     * adds a NullHandler if `streams` and `files` and `handlers` are all `None`
 186     * convenience functions to add most frequently used handlers
 187
 188     ..note:: Creating multiple instances with the same name is not allowed and
 189              will result in an error. Use :py:func:`get_logger` instead of this
 190              constructor to avoid such situtations
 191
 192     ..note:: Do not change or use the underlying logger or functionality here
 193              (in particular, get_level) is no longer reliable!
 194     """
 195
 196     def __init__(self, name, level=INFO, fmt=DEFAULT_SHORT_LEVEL_FORMAT,
 197                  datefmt=DEFAULT_SHORT_LEVEL_DATE_FORMAT,
 198                  streams=STDOUT, files=None, handlers=None):
 199         """
 200         Creates a I2nLogger; forwards args to logging.getLogger
 201
 202         :param str name: name of this logger, best practice is module name
 203         :param int level: best use one of the constants DEBUG, INFO NOTICE,
 204                           WARNING, ERROR
 205         :param str fmt: format of log messages, see
 206                         :py:class:`ShortLevelFormatter` for more help
 207         :param str datefmt: format of date added to log messages, see
 208                             :py:class:`ShortLevelFormatter` for more help
 209         :param streams: list/tuple of or a single stream to log to, default is
 210                         STDOUT (=sys.stdout)
 211         :type streams: (:py:class:`io.IOBase`) or [:py:class:`io.IOBase`) or
 212                        None
 213         :param files: list/tuple or single file name to log to
 214         :type files: None or (str) or [str]
 215         :param handlers: other handlers to customize and use with this logger
 216         :type handlers: None or [:py:class:`logging.Handler`] or
 217                         (:py:class:`logging.Handler`)
 218         :raise: ValueError if an I2nLogger with the same name exists already
 219         """
 220
 221         # check if an instance with the same name has been created earlier
 222         # to prevent conflicts
 223         global _i2n_loggers
 224         if name in _i2n_loggers:
 225             raise ValueError("An I2nLogger with that exact name ('{0}') exists"
 226                              " already -- use get_logger instead!"
 227                              .format(name))
 228
 229         self._log = logging.getLogger(name)
 230         if isinstance(level, str):
 231             level = LEVEL_DICT[level]
 232         self._level = min(MAX_LEVEL, max(MIN_LEVEL, level))
 233         self._log.setLevel(self._level)
 234
 235         # remove handlers (sometimes there are mutliple by default)
 236         for handler in self._log.handlers:
 237             self._log.removeHandler(handler)
 238
 239         # create new handlers and formatter
 240         if streams is None:
 241             streams = []
 242         elif not isinstance(streams, (list, tuple)):
 243             streams = (streams, )
 244         for stream in streams:
 245             formatter = ShortLevelFormatter(fmt=fmt, datefmt=datefmt)
 246             formatter.add_level(NOTICE, 'note')
 247             new_handler = logging.StreamHandler(stream)
 248             new_handler.setFormatter(formatter)
 249             new_handler.setLevel(self._level)
 250             self._log.addHandler(new_handler)
 251
 252         if files is None:
 253             files = []
 254         elif not isinstance(files, (list, tuple)):
 255             files = (files, )
 256         for file_name in files:
 257             formatter = ShortLevelFormatter(fmt=fmt, datefmt=datefmt)
 258             formatter.add_level(NOTICE, 'note')
 259             new_handler = logging.FileHandler(file_name)
 260             new_handler.setFormatter(formatter)
 261             new_handler.setLevel(self._level)
 262             self._log.addHandler(new_handler)
 263
 264         if handlers is None:
 265             handlers = []
 266         elif not isinstance(handlers, (list, tuple)):
 267             handlers = (handlers, )
 268         for handler in handlers:
 269             formatter = ShortLevelFormatter(fmt=fmt, datefmt=datefmt)
 270             formatter.add_level(NOTICE, 'note')
 271             handler.setFormatter(formatter)
 272             handler.setLevel(self._level)
 273             self._log.addHandler(handler)
 274
 275         if not self._log.handlers:
 276             self._log.addHandler(logging.NullHandler())
 277
 278         # remember that this logger is a I2nLogger
 279         _i2n_loggers[name] = self
 280
 281     def dbg(self, message, *args, **kwargs):
 282         self._log_no_test(DEBUG, message, *args, **kwargs)
 283
 284     def debug(self, message, *args, **kwargs):
 285         self._log_no_test(DEBUG, message, *args, **kwargs)
 286
 287     def info(self, message, *args, **kwargs):
 288         self._log_no_test(INFO, message, *args, **kwargs)
 289
 290     def note(self, message, *args, **kwargs):
 291         self._log_no_test(NOTICE, message, *args, **kwargs)
 292
 293     def notice(self, message, *args, **kwargs):
 294         self._log_no_test(NOTICE, message, *args, **kwargs)
 295
 296     def warn(self, message, *args, **kwargs):
 297         self._log_no_test(WARNING, message, *args, **kwargs)
 298
 299     def warning(self, message, *args, **kwargs):
 300         self._log_no_test(WARNING, message, *args, **kwargs)
 301
 302     def err(self, message, *args, **kwargs):
 303         self._log_no_test(ERROR, message, *args, **kwargs)
 304
 305     def error(self, message, *args, **kwargs):
 306         self._log_no_test(ERROR, message, *args, **kwargs)
 307
 308     def exception(self, message, *args, **kwargs):
 309         if 'exc_info' in kwargs:
 310             self._log_no_test(ERROR, message, *args, **kwargs)
 311         else:
 312             self._log_no_test(ERROR, message, *args, exc_info=True, **kwargs)
 313
 314     def critical(self, message, *args, **kwargs):
 315         self._log_no_test(CRITICAL, message, *args, **kwargs)
 316
 317     def log(self, level, message, *args, **kwargs):
 318         if isinstance(level, str):
 319             level = LEVEL_DICT[level.lower()]
 320         if level >= self._level:
 321             try:
 322                 message_formatted = message.format(*args)
 323             except (KeyError, IndexError):
 324                 message_formatted = '[LOG ARGS!] ' + message
 325             self._log.log(level, message_formatted, **kwargs)
 326
 327     def _log_no_test(self, level, message, *args, **kwargs):
 328         """Same as log() but without the isinstance test for internal use."""
 329         if level >= self._level:
 330             try:
 331                 message_formatted = message.format(*args)
 332             except (KeyError, IndexError):
 333                 message_formatted = '[LOG ARGS!] ' + message
 334             self._log.log(level, message_formatted, **kwargs)
 335
 336     def log_count_if_interesting(self, count, level=INFO, counter_name=None):
 337         """
 338         Log value of a counter in gradually coarser intervals
 339
 340         See :py:func:`is_interesting_count` for definition of "interesting".
 341         """
 342         if is_interesting_count(count):
 343             if counter_name:
 344                 self.log(level, '{0} counter is at {1}', counter_name, count)
 345             else:
 346                 self.log(level, 'Counter is at {0}', count)
 347
 348     def get_level(self):
 349         """Return int level of this logger."""
 350         return self._level
 351
 352     def get_level_str(self):
 353         """Returns :py:func:`logging.getLevelName` on :py:meth:`get_level`."""
 354         return logging.getLevelName(self._level)
 355
 356     def set_level(self, new_level):
 357         """
 358         Set level given an int or a str.
 359
 360         :arg new_level: int or str (str is converted to lower case)
 361         :raises: KeyError if new_level is a string that is not in
 362                  :py:data:`LEVEL_DICT`
 363         """
 364         if isstr(new_level):
 365             self._level = LEVEL_DICT[new_level.lower()]
 366         else:
 367             self._level = min(MAX_LEVEL, max(MIN_LEVEL, new_level))
 368         self._log.setLevel(self._level)
 369         for handler in self._log.handlers:
 370             handler.setLevel(self._level)
 371
 372     def add_handler(self, *args, **kwargs):
 373         return self._log.addHandler(*args, **kwargs)
 374
 375     def add_stream_handler(self, stream=sys.stdout, level='debug'):
 376         """
 377         Add a stream handler to the current logger that logs to given stream.
 378
 379         Note that the default here is stdout, not the python-default (stderr).
 380         """
 381         handler = logging.StreamHandler(stream)
 382         handler.setLevel(self._level)
 383         self._log.addHandler(handler)
 384
 385     def add_syslog_handler(self):
 386         """Add a handler that logs to syslog."""
 387         handler = SysLogHandler(address='/dev/log')
 388         handler.setLevel(self._level)
 389         self._log.addHandler(handler)
 390
 391     def add_file_handler(self, filename, mode='a', max_bytes=5*1024*1024,
 392                          max_rotations=100, **kwargs):
 393         """
 394         Add a handler that logs to given file.
 395
 396         For convenience creates a
 397         :py:class:`logging.handlers.RotatingFileHandler` to avoid huge log
 398         files filling up the disc in case of error.
 399
 400         :param str filename: path to file that logger should write to
 401         :param str mode: Mode with which to open log file; forwarded to handler
 402         :param int max_bytes: Max size in bytes of a log file before it is
 403                               renamed to `[filename].1` and logging continues
 404                               with an empty `[filename]`.
 405         :param int max_rotations: Max number of rotated files to keep
 406         :param dict kwargs: All other args (e.g. `encoding`) are forwarded to
 407                             handler constructor. `maxBytes` and `backupCount`
 408                             are overwritten with `max_bytes` and `max_rots`.
 409         """
 410         kwargs['maxBytes'] = max_bytes
 411         kwargs['backupCount'] = max_rotations
 412         handler = RotatingFileHandler(filename, mode, **kwargs)
 413         handler.setLevel(self._level)
 414         self._log.addHandler(handler)
 415
 416
 417 def n_digits(number):
 418     """
 419     Returns the number of digits a number has in decimal format
 420
 421     :returns: 1 for 1...9, 2 for 10...99, 3 for 100...999, ...
 422               0 for 0 (and everything else between -1 and 1)
 423               1 for -1...-9, 2 for -10...-99, ...
 424     """
 425     if abs(number) < 1:
 426         return 0
 427     else:
 428         return floor(log10(abs(number)))+1
 429
 430
 431 def is_interesting_count(counter):
 432     """
 433     Return True if counter has reached an "interesting" value
 434
 435     For the counter to be "interesting" becomes ever harder. At first it is
 436     easy (returns True for 1,2,3,6,10), then becomes harder (True only for
 437     10,20,30,60,100) and harder (True for 100,200,300,600,1000) and this scheme
 438     continues on a logartihmic scale.
 439
 440     An example that will print lots in the beginning and then less and less::
 441
 442         counter = 0
 443         while not end_reached():
 444             do_something()
 445             if is_interesting_count(counter):
 446                 log('reached iteration {0}'.format(counter))
 447             counter += 1
 448
 449     Used by :py:meth:`I2nLogger::log_count_if_interesting`.
 450
 451     :returns: True for a few values of counter, False most of the time
 452     """
 453     return float(counter) / 10.**(n_digits(counter)-1.) in (1., 2., 3., 6.)