logging_utils.py

   1 #!/usr/bin/env python3
   2
   3 """Utilities related to logging."""
   4
   5 import collections
   6 import contextlib
   7 import datetime
   8 import enum
   9 import io
  10 import logging
  11 from logging.handlers import RotatingFileHandler, SysLogHandler
  12 import os
  13 import pytz
  14 import random
  15 import sys
  16 from typing import Callable, Iterable, Mapping, Optional
  17
  18 from overrides import overrides
  19
  20 # This module is commonly used by others in here and should avoid
  21 # taking any unnecessary dependencies back on them.
  22 import argparse_utils
  23 import config
  24
  25 cfg = config.add_commandline_args(
  26     f'Logging ({__file__})',
  27     'Args related to logging')
  28 cfg.add_argument(
  29     '--logging_config_file',
  30     type=argparse_utils.valid_filename,
  31     default=None,
  32     metavar='FILENAME',
  33     help='Config file containing the logging setup, see: https://docs.python.org/3/howto/logging.html#logging-advanced-tutorial',
  34 )
  35 cfg.add_argument(
  36     '--logging_level',
  37     type=str,
  38     default='INFO',
  39     choices=['NOTSET', 'DEBUG', 'INFO', 'WARNING', 'ERROR', 'CRITICAL'],
  40     metavar='LEVEL',
  41     help='The global default level below which to squelch log messages; see also --lmodule',
  42 )
  43 cfg.add_argument(
  44     '--logging_format',
  45     type=str,
  46     default=None,
  47     help='The format for lines logged via the logger module.  See: https://docs.python.org/3/library/logging.html#formatter-objects'
  48 )
  49 cfg.add_argument(
  50     '--logging_date_format',
  51     type=str,
  52     default='%Y/%m/%dT%H:%M:%S.%f%z',
  53     metavar='DATEFMT',
  54     help='The format of any dates in --logging_format.'
  55 )
  56 cfg.add_argument(
  57     '--logging_console',
  58     action=argparse_utils.ActionNoYes,
  59     default=True,
  60     help='Should we log to the console (stderr)',
  61 )
  62 cfg.add_argument(
  63     '--logging_filename',
  64     type=str,
  65     default=None,
  66     metavar='FILENAME',
  67     help='The filename of the logfile to write.'
  68 )
  69 cfg.add_argument(
  70     '--logging_filename_maxsize',
  71     type=int,
  72     default=(1024*1024),
  73     metavar='#BYTES',
  74     help='The maximum size (in bytes) to write to the logging_filename.'
  75 )
  76 cfg.add_argument(
  77     '--logging_filename_count',
  78     type=int,
  79     default=7,
  80     metavar='COUNT',
  81     help='The number of logging_filename copies to keep before deleting.'
  82 )
  83 cfg.add_argument(
  84     '--logging_syslog',
  85     action=argparse_utils.ActionNoYes,
  86     default=False,
  87     help='Should we log to localhost\'s syslog.'
  88 )
  89 cfg.add_argument(
  90     '--logging_syslog_facility',
  91     type=str,
  92     default = 'USER',
  93     choices=['NOTSET', 'AUTH', 'AUTH_PRIV', 'CRON', 'DAEMON', 'FTP', 'KERN', 'LPR', 'MAIL', 'NEWS',
  94              'SYSLOG', 'USER', 'UUCP', 'LOCAL0', 'LOCAL1', 'LOCAL2', 'LOCAL3', 'LOCAL4', 'LOCAL5',
  95              'LOCAL6', 'LOCAL7'],
  96     metavar='SYSLOG_FACILITY_LIST',
  97     help='The default syslog message facility identifier',
  98 )
  99 cfg.add_argument(
 100     '--logging_debug_threads',
 101     action=argparse_utils.ActionNoYes,
 102     default=False,
 103     help='Should we prepend pid/tid data to all log messages?'
 104 )
 105 cfg.add_argument(
 106     '--logging_debug_modules',
 107     action=argparse_utils.ActionNoYes,
 108     default=False,
 109     help='Should we prepend module/function data to all log messages?'
 110 )
 111 cfg.add_argument(
 112     '--logging_info_is_print',
 113     action=argparse_utils.ActionNoYes,
 114     default=False,
 115     help='logging.info also prints to stdout.'
 116 )
 117 cfg.add_argument(
 118     '--logging_squelch_repeats_enabled',
 119     action=argparse_utils.ActionNoYes,
 120     default=True,
 121     help='Do we allow code to indicate that it wants to squelch repeated logging messages or should we always log?'
 122 )
 123 cfg.add_argument(
 124     '--logging_probabilistically_enabled',
 125     action=argparse_utils.ActionNoYes,
 126     default=True,
 127     help='Do we allow probabilistic logging (for code that wants it) or should we always log?'
 128 )
 129 # See also: OutputMultiplexer
 130 cfg.add_argument(
 131     '--logging_captures_prints',
 132     action=argparse_utils.ActionNoYes,
 133     default=False,
 134     help='When calling print, also log.info automatically.'
 135 )
 136 cfg.add_argument(
 137     '--lmodule',
 138     type=str,
 139     metavar='<SCOPE>=<LEVEL>[,<SCOPE>=<LEVEL>...]',
 140     help=(
 141         'Allows per-scope logging levels which override the global level set with --logging-level.' +
 142         'Pass a space separated list of <scope>=<level> where <scope> is one of: module, ' +
 143         'module:function, or :function and <level> is a logging level (e.g. INFO, DEBUG...)'
 144     )
 145 )
 146
 147
 148 built_in_print = print
 149
 150
 151 def function_identifier(f: Callable) -> str:
 152     """
 153     Given a callable function, return a string that identifies it.
 154     Usually that string is just __module__:__name__ but there's a
 155     corner case: when __module__ is __main__ (i.e. the callable is
 156     defined in the same module as __main__).  In this case,
 157     f.__module__ returns "__main__" instead of the file that it is
 158     defined in.  Work around this using pathlib.Path (see below).
 159
 160     >>> function_identifier(function_identifier)
 161     'logging_utils:function_identifier'
 162
 163     """
 164     if f.__module__ == '__main__':
 165         from pathlib import Path
 166         import __main__
 167         module = __main__.__file__
 168         module = Path(module).stem
 169         return f'{module}:{f.__name__}'
 170     else:
 171         return f'{f.__module__}:{f.__name__}'
 172
 173
 174 # A map from logging_callsite_id -> count of logged messages.
 175 squelched_logging_counts: Mapping[str, int] = {}
 176
 177
 178 def squelch_repeated_log_messages(squelch_after_n_repeats: int) -> Callable:
 179     """
 180     A decorator that marks a function as interested in having the logging
 181     messages that it produces be squelched (ignored) after it logs the
 182     same message more than N times.
 183
 184     Note: this decorator affects *ALL* logging messages produced
 185     within the decorated function.  That said, messages must be
 186     identical in order to be squelched.  For example, if the same line
 187     of code produces different messages (because of, e.g., a format
 188     string), the messages are considered to be different.
 189
 190     """
 191     def squelch_logging_wrapper(f: Callable):
 192         identifier = function_identifier(f)
 193         squelched_logging_counts[identifier] = squelch_after_n_repeats
 194         return f
 195     return squelch_logging_wrapper
 196
 197
 198 class SquelchRepeatedMessagesFilter(logging.Filter):
 199     """
 200     A filter that only logs messages from a given site with the same
 201     (exact) message at the same logging level N times and ignores
 202     subsequent attempts to log.
 203
 204     This filter only affects logging messages that repeat more than
 205     a threshold number of times from functions that are tagged with
 206     the @logging_utils.squelched_logging_ok decorator.
 207
 208     """
 209     def __init__(self) -> None:
 210         self.counters = collections.Counter()
 211         super().__init__()
 212
 213     @overrides
 214     def filter(self, record: logging.LogRecord) -> bool:
 215         id1 = f'{record.module}:{record.funcName}'
 216         if id1 not in squelched_logging_counts:
 217             return True
 218         threshold = squelched_logging_counts[id1]
 219         logsite = f'{record.pathname}+{record.lineno}+{record.levelno}+{record.msg}'
 220         count = self.counters[logsite]
 221         self.counters[logsite] += 1
 222         return count < threshold
 223
 224
 225 class DynamicPerScopeLoggingLevelFilter(logging.Filter):
 226     """Only interested in seeing logging messages from an allow list of
 227     module names or module:function names.  Block others.
 228
 229     """
 230     @staticmethod
 231     def level_name_to_level(name: str) -> int:
 232         numeric_level = getattr(
 233             logging,
 234             name,
 235             None
 236         )
 237         if not isinstance(numeric_level, int):
 238             raise ValueError('Invalid level: {name}')
 239         return numeric_level
 240
 241     def __init__(
 242             self,
 243             default_logging_level: int,
 244             per_scope_logging_levels: str,
 245     ) -> None:
 246         super().__init__()
 247         self.valid_levels = set(['NOTSET', 'DEBUG', 'INFO', 'WARNING', 'ERROR', 'CRITICAL'])
 248         self.default_logging_level = default_logging_level
 249         self.level_by_scope = {}
 250         if per_scope_logging_levels is not None:
 251             for chunk in per_scope_logging_levels.split(','):
 252                 if '=' not in chunk:
 253                     print(
 254                         f'Malformed lmodule directive: "{chunk}", missing "=".  Ignored.',
 255                         file=sys.stderr
 256                     )
 257                     continue
 258                 try:
 259                     (scope, level) = chunk.split('=')
 260                 except ValueError:
 261                     print(
 262                         f'Malformed lmodule directive: "{chunk}".  Ignored.',
 263                         file=sys.stderr
 264                     )
 265                     continue
 266                 scope = scope.strip()
 267                 level = level.strip().upper()
 268                 if level not in self.valid_levels:
 269                     print(
 270                         f'Malformed lmodule directive: "{chunk}", bad level.  Ignored.',
 271                         file=sys.stderr
 272                     )
 273                     continue
 274                 self.level_by_scope[scope] = (
 275                     DynamicPerScopeLoggingLevelFilter.level_name_to_level(
 276                         level
 277                     )
 278                 )
 279
 280     @overrides
 281     def filter(self, record: logging.LogRecord) -> bool:
 282         # First try to find a logging level by scope (--lmodule)
 283         if len(self.level_by_scope) > 0:
 284             min_level = None
 285             for scope in (
 286                     record.module,
 287                     f'{record.module}:{record.funcName}',
 288                     f':{record.funcName}'
 289             ):
 290                 level = self.level_by_scope.get(scope, None)
 291                 if level is not None:
 292                     if min_level is None or level < min_level:
 293                         min_level = level
 294
 295             # If we found one, use it instead of the global default level.
 296             if min_level is not None:
 297                 return record.levelno >= min_level
 298
 299         # Otherwise, use the global logging level (--logging_level)
 300         return record.levelno >= self.default_logging_level
 301
 302
 303 # A map from function_identifier -> probability of logging (0.0%..100.0%)
 304 probabilistic_logging_levels: Mapping[str, float] = {}
 305
 306
 307 def logging_is_probabilistic(probability_of_logging: float) -> Callable:
 308     """
 309     A decorator that indicates that all logging statements within the
 310     scope of a particular (marked) function are not deterministic
 311     (i.e. they do not always unconditionally log) but rather are
 312     probabilistic (i.e. they log N% of the time randomly).
 313
 314     This affects *ALL* logging statements within the marked function.
 315
 316     """
 317     def probabilistic_logging_wrapper(f: Callable):
 318         identifier = function_identifier(f)
 319         probabilistic_logging_levels[identifier] = probability_of_logging
 320         return f
 321     return probabilistic_logging_wrapper
 322
 323
 324 class ProbabilisticFilter(logging.Filter):
 325     """
 326     A filter that logs messages probabilistically (i.e. randomly at some
 327     percent chance).
 328
 329     This filter only affects logging messages from functions that have
 330     been tagged with the @logging_utils.probabilistic_logging decorator.
 331
 332     """
 333     @overrides
 334     def filter(self, record: logging.LogRecord) -> bool:
 335         id1 = f'{record.module}:{record.funcName}'
 336         if id1 not in probabilistic_logging_levels:
 337             return True
 338         threshold = probabilistic_logging_levels[id1]
 339         return (random.random() * 100.0) <= threshold
 340
 341
 342 class OnlyInfoFilter(logging.Filter):
 343     """
 344     A filter that only logs messages produced at the INFO logging
 345     level.  This is used by the logging_info_is_print commandline
 346     option to select a subset of the logging stream to send to a
 347     stdout handler.
 348
 349     """
 350     @overrides
 351     def filter(self, record: logging.LogRecord):
 352         return record.levelno == logging.INFO
 353
 354
 355 class MillisecondAwareFormatter(logging.Formatter):
 356     """
 357     A formatter for adding milliseconds to log messages.
 358
 359     """
 360     converter = datetime.datetime.fromtimestamp
 361
 362     @overrides
 363     def formatTime(self, record, datefmt=None):
 364         ct = MillisecondAwareFormatter.converter(
 365             record.created, pytz.timezone("US/Pacific")
 366         )
 367         if datefmt:
 368             s = ct.strftime(datefmt)
 369         else:
 370             t = ct.strftime("%Y-%m-%d %H:%M:%S")
 371             s = "%s,%03d" % (t, record.msecs)
 372         return s
 373
 374
 375 def initialize_logging(logger=None) -> logging.Logger:
 376     assert config.has_been_parsed()
 377     if logger is None:
 378         logger = logging.getLogger()       # Root logger
 379
 380     if config.config['logging_config_file'] is not None:
 381         logging.config.fileConfig('logging.conf')
 382         return logger
 383
 384     handlers = []
 385
 386     # Global default logging level (--logging_level)
 387     default_logging_level = getattr(
 388         logging,
 389         config.config['logging_level'].upper(),
 390         None
 391     )
 392     if not isinstance(default_logging_level, int):
 393         raise ValueError('Invalid level: %s' % config.config['logging_level'])
 394
 395     if config.config['logging_format']:
 396         fmt = config.config['logging_format']
 397     else:
 398         if config.config['logging_syslog']:
 399             fmt = '%(levelname).1s:%(filename)s[%(process)d]: %(message)s'
 400         else:
 401             fmt = '%(levelname).1s:%(asctime)s: %(message)s'
 402
 403     if config.config['logging_debug_threads']:
 404         fmt = f'%(process)d.%(thread)d|{fmt}'
 405     if config.config['logging_debug_modules']:
 406         fmt = f'%(filename)s:%(funcName)s:%(lineno)s|{fmt}'
 407
 408     if config.config['logging_syslog']:
 409         if sys.platform not in ('win32', 'cygwin'):
 410             if config.config['logging_syslog_facility']:
 411                 facility_name = 'LOG_' + config.config['logging_syslog_facility']
 412             facility = SysLogHandler.__dict__.get(facility_name, SysLogHandler.LOG_USER)
 413             handler = SysLogHandler(facility=SysLogHandler.LOG_CRON, address='/dev/log')
 414             handler.setFormatter(
 415                 MillisecondAwareFormatter(
 416                     fmt=fmt,
 417                     datefmt=config.config['logging_date_format'],
 418                 )
 419             )
 420             handlers.append(handler)
 421
 422     if config.config['logging_filename']:
 423         handler = RotatingFileHandler(
 424             config.config['logging_filename'],
 425             maxBytes = config.config['logging_filename_maxsize'],
 426             backupCount = config.config['logging_filename_count'],
 427         )
 428         handler.setFormatter(
 429             MillisecondAwareFormatter(
 430                 fmt=fmt,
 431                 datefmt=config.config['logging_date_format'],
 432             )
 433         )
 434         handlers.append(handler)
 435
 436     if config.config['logging_console']:
 437         handler = logging.StreamHandler(sys.stderr)
 438         handler.setFormatter(
 439             MillisecondAwareFormatter(
 440                 fmt=fmt,
 441                 datefmt=config.config['logging_date_format'],
 442             )
 443         )
 444         handlers.append(handler)
 445
 446     if len(handlers) == 0:
 447         handlers.append(logging.NullHandler())
 448
 449     for handler in handlers:
 450         logger.addHandler(handler)
 451
 452     if config.config['logging_info_is_print']:
 453         handler = logging.StreamHandler(sys.stdout)
 454         handler.addFilter(OnlyInfoFilter())
 455         logger.addHandler(handler)
 456
 457     if config.config['logging_squelch_repeats_enabled']:
 458         for handler in handlers:
 459             handler.addFilter(SquelchRepeatedMessagesFilter())
 460
 461     if config.config['logging_probabilistically_enabled']:
 462         for handler in handlers:
 463             handler.addFilter(ProbabilisticFilter())
 464
 465     for handler in handlers:
 466         handler.addFilter(
 467             DynamicPerScopeLoggingLevelFilter(
 468                 default_logging_level,
 469                 config.config['lmodule'],
 470             )
 471         )
 472     logger.setLevel(0)
 473     logger.propagate = False
 474
 475     if config.config['logging_captures_prints']:
 476         import builtins
 477         global built_in_print
 478
 479         def print_and_also_log(*arg, **kwarg):
 480             f = kwarg.get('file', None)
 481             if f == sys.stderr:
 482                 logger.warning(*arg)
 483             else:
 484                 logger.info(*arg)
 485             built_in_print(*arg, **kwarg)
 486         builtins.print = print_and_also_log
 487
 488     return logger
 489
 490
 491 def get_logger(name: str = ""):
 492     logger = logging.getLogger(name)
 493     return initialize_logging(logger)
 494
 495
 496 def tprint(*args, **kwargs) -> None:
 497     """Legacy function for printing a message augmented with thread id."""
 498
 499     if config.config['logging_debug_threads']:
 500         from thread_utils import current_thread_id
 501         print(f'{current_thread_id()}', end="")
 502         print(*args, **kwargs)
 503     else:
 504         pass
 505
 506
 507 def dprint(*args, **kwargs) -> None:
 508     """Legacy function used to print to stderr."""
 509
 510     print(*args, file=sys.stderr, **kwargs)
 511
 512
 513 class OutputMultiplexer(object):
 514     """
 515     A class that broadcasts printed messages to several sinks (including
 516     various logging levels, different files, different file handles,
 517     the house log, etc...)
 518
 519     """
 520     class Destination(enum.IntEnum):
 521         """Bits in the destination_bitv bitvector.  Used to indicate the
 522         output destination."""
 523         LOG_DEBUG = 0x01         #  ⎫
 524         LOG_INFO = 0x02          #  ⎪
 525         LOG_WARNING = 0x04       #  ⎬ Must provide logger to the c'tor.
 526         LOG_ERROR = 0x08         #  ⎪
 527         LOG_CRITICAL = 0x10      #  ⎭
 528         FILENAMES = 0x20         # Must provide a filename to the c'tor.
 529         FILEHANDLES = 0x40       # Must provide a handle to the c'tor.
 530         HLOG = 0x80
 531         ALL_LOG_DESTINATIONS = (
 532             LOG_DEBUG | LOG_INFO | LOG_WARNING | LOG_ERROR | LOG_CRITICAL
 533         )
 534         ALL_OUTPUT_DESTINATIONS = 0x8F
 535
 536     def __init__(self,
 537                  destination_bitv: int,
 538                  *,
 539                  logger=None,
 540                  filenames: Optional[Iterable[str]] = None,
 541                  handles: Optional[Iterable[io.TextIOWrapper]] = None):
 542         if logger is None:
 543             logger = logging.getLogger(None)
 544         self.logger = logger
 545
 546         if filenames is not None:
 547             self.f = [
 548                 open(filename, 'wb', buffering=0) for filename in filenames
 549             ]
 550         else:
 551             if destination_bitv & OutputMultiplexer.FILENAMES:
 552                 raise ValueError(
 553                     "Filenames argument is required if bitv & FILENAMES"
 554                 )
 555             self.f = None
 556
 557         if handles is not None:
 558             self.h = [handle for handle in handles]
 559         else:
 560             if destination_bitv & OutputMultiplexer.Destination.FILEHANDLES:
 561                 raise ValueError(
 562                     "Handle argument is required if bitv & FILEHANDLES"
 563                 )
 564             self.h = None
 565
 566         self.set_destination_bitv(destination_bitv)
 567
 568     def get_destination_bitv(self):
 569         return self.destination_bitv
 570
 571     def set_destination_bitv(self, destination_bitv: int):
 572         if destination_bitv & self.Destination.FILENAMES and self.f is None:
 573             raise ValueError(
 574                 "Filename argument is required if bitv & FILENAMES"
 575             )
 576         if destination_bitv & self.Destination.FILEHANDLES and self.h is None:
 577             raise ValueError(
 578                     "Handle argument is required if bitv & FILEHANDLES"
 579                 )
 580         self.destination_bitv = destination_bitv
 581
 582     def print(self, *args, **kwargs):
 583         from string_utils import sprintf, strip_escape_sequences
 584         end = kwargs.pop("end", None)
 585         if end is not None:
 586             if not isinstance(end, str):
 587                 raise TypeError("end must be None or a string")
 588         sep = kwargs.pop("sep", None)
 589         if sep is not None:
 590             if not isinstance(sep, str):
 591                 raise TypeError("sep must be None or a string")
 592         if kwargs:
 593             raise TypeError("invalid keyword arguments to print()")
 594         buf = sprintf(*args, end="", sep=sep)
 595         if sep is None:
 596             sep = " "
 597         if end is None:
 598             end = "\n"
 599         if end == '\n':
 600             buf += '\n'
 601         if (
 602                 self.destination_bitv & self.Destination.FILENAMES and
 603                 self.f is not None
 604         ):
 605             for _ in self.f:
 606                 _.write(buf.encode('utf-8'))
 607                 _.flush()
 608
 609         if (
 610                 self.destination_bitv & self.Destination.FILEHANDLES and
 611                 self.h is not None
 612         ):
 613             for _ in self.h:
 614                 _.write(buf)
 615                 _.flush()
 616
 617         buf = strip_escape_sequences(buf)
 618         if self.logger is not None:
 619             if self.destination_bitv & self.Destination.LOG_DEBUG:
 620                 self.logger.debug(buf)
 621             if self.destination_bitv & self.Destination.LOG_INFO:
 622                 self.logger.info(buf)
 623             if self.destination_bitv & self.Destination.LOG_WARNING:
 624                 self.logger.warning(buf)
 625             if self.destination_bitv & self.Destination.LOG_ERROR:
 626                 self.logger.error(buf)
 627             if self.destination_bitv & self.Destination.LOG_CRITICAL:
 628                 self.logger.critical(buf)
 629         if self.destination_bitv & self.Destination.HLOG:
 630             hlog(buf)
 631
 632     def close(self):
 633         if self.f is not None:
 634             for _ in self.f:
 635                 _.close()
 636
 637
 638 class OutputMultiplexerContext(OutputMultiplexer, contextlib.ContextDecorator):
 639     """
 640     A context that uses an OutputMultiplexer.  e.g.
 641
 642         with OutputMultiplexerContext(
 643                 OutputMultiplexer.LOG_INFO |
 644                 OutputMultiplexer.LOG_DEBUG |
 645                 OutputMultiplexer.FILENAMES |
 646                 OutputMultiplexer.FILEHANDLES,
 647                 filenames = [ '/tmp/foo.log', '/var/log/bar.log' ],
 648                 handles = [ f, g ]
 649             ) as mplex:
 650                 mplex.print("This is a log message!")
 651
 652     """
 653     def __init__(self,
 654                  destination_bitv: OutputMultiplexer.Destination,
 655                  *,
 656                  logger = None,
 657                  filenames = None,
 658                  handles = None):
 659         super().__init__(
 660             destination_bitv,
 661             logger=logger,
 662             filenames=filenames,
 663             handles=handles)
 664
 665     def __enter__(self):
 666         return self
 667
 668     def __exit__(self, etype, value, traceback) -> bool:
 669         super().close()
 670         if etype is not None:
 671             return False
 672         return True
 673
 674
 675 def hlog(message: str) -> None:
 676     """Write a message to the house log."""
 677
 678     message = message.replace("'", "'\"'\"'")
 679     os.system(f"/usr/bin/logger -p local7.info -- '{message}'")
 680
 681
 682 if __name__ == '__main__':
 683     import doctest
 684     doctest.testmod()