src/pyutils/logging_utils.py

   1 #!/usr/bin/env python3
   2 # -*- coding: utf-8 -*-
   3
   4 # © Copyright 2021-2022, Scott Gasch
   5
   6 """
   7 This is a module that offers an opinionated take on how whole program
   8 logging should be initialized and controlled.  It uses the standard
   9 Python :mod:`logging` but gives you control, via commandline config,
  10 to do things such as:
  11
  12     * Set the logging default level (debug, info, warning, error, critical)
  13       of the whole program (see: :code:`--logging_level`)... and to override
  14       the logging level for individual modules/functions based on their names
  15       (see :code:`--lmodule`),
  16     * define the logging message format (see :code:`--logging_format` and
  17       :code:`--logging_date_format`) including easily adding a PID/TID
  18       marker on all messages to help with multithreaded debugging
  19       (:code:`--logging_debug_threads`) and force module names of code
  20       that emits log messages to be included in the format
  21       (:code:`--logging_debug_modules`),
  22     * control the destination of logged messages:
  23
  24         - log to the console/stderr (:code:`--logging_console`) and/or
  25         - log to a rotated file (:code:`--logging_filename`,
  26           :code:`--logging_filename_maxsize` and :code:`--logging_filename_count`)
  27           and/or
  28         - log to the UNIX syslog (:code:`--logging_syslog` and
  29           :code:`--logging_syslog_facility`)
  30
  31     * optionally squelch repeated messages (:code:`--logging_squelch_repeats`),
  32     * optionally log probalistically (:code:`--logging_probabilistically`),
  33     * capture printed messages into the info log (:code:`--logging_captures_prints`),
  34     * and optionally clear unwanted logging handlers added by other imports
  35       before this one (:code:`--logging_clear_preexisting_handlers`).
  36
  37 To use this functionality, call :meth:`initialize_logging` early
  38 in your program entry point.  If you use the
  39 :meth:`pyutils.bootstrap.initialize` decorator on your program's entry
  40 point, it will call this for you automatically.
  41 """
  42
  43 import collections
  44 import contextlib
  45 import datetime
  46 import enum
  47 import io
  48 import logging
  49 import os
  50 import random
  51 import sys
  52 from logging.config import fileConfig
  53 from logging.handlers import RotatingFileHandler, SysLogHandler
  54 from typing import Any, Callable, Dict, Iterable, List, Optional
  55
  56 import pytz
  57 from overrides import overrides
  58
  59 # This module is commonly used by others in here and should avoid
  60 # taking any unnecessary dependencies back on them.
  61 from pyutils import argparse_utils, config
  62
  63 cfg = config.add_commandline_args(f'Logging ({__file__})', 'Args related to logging')
  64 cfg.add_argument(
  65     '--logging_config_file',
  66     type=argparse_utils.valid_filename,
  67     default=None,
  68     metavar='FILENAME',
  69     help='Config file containing the logging setup, see: https://docs.python.org/3/howto/logging.html#logging-advanced-tutorial',
  70 )
  71 cfg.add_argument(
  72     '--logging_level',
  73     type=str,
  74     default='INFO',
  75     choices=['NOTSET', 'DEBUG', 'INFO', 'WARNING', 'ERROR', 'CRITICAL'],
  76     metavar='LEVEL',
  77     help='The global default level below which to squelch log messages; see also --lmodule',
  78 )
  79 cfg.add_argument(
  80     '--logging_format',
  81     type=str,
  82     default=None,
  83     help='The format for lines logged via the logger module.  See: https://docs.python.org/3/library/logging.html#formatter-objects',
  84 )
  85 cfg.add_argument(
  86     '--logging_date_format',
  87     type=str,
  88     default='%Y/%m/%dT%H:%M:%S.%f%z',
  89     metavar='DATEFMT',
  90     help='The format of any dates in --logging_format.',
  91 )
  92 cfg.add_argument(
  93     '--logging_console',
  94     action=argparse_utils.ActionNoYes,
  95     default=True,
  96     help='Should we log to the console (stderr)',
  97 )
  98 cfg.add_argument(
  99     '--logging_filename',
 100     type=str,
 101     default=None,
 102     metavar='FILENAME',
 103     help='The filename of the logfile to write.',
 104 )
 105 cfg.add_argument(
 106     '--logging_filename_maxsize',
 107     type=int,
 108     default=(1024 * 1024),
 109     metavar='#BYTES',
 110     help='The maximum size (in bytes) to write to the logging_filename.',
 111 )
 112 cfg.add_argument(
 113     '--logging_filename_count',
 114     type=int,
 115     default=7,
 116     metavar='COUNT',
 117     help='The number of logging_filename copies to keep before deleting.',
 118 )
 119 cfg.add_argument(
 120     '--logging_syslog',
 121     action=argparse_utils.ActionNoYes,
 122     default=False,
 123     help='Should we log to localhost\'s syslog.',
 124 )
 125 cfg.add_argument(
 126     '--logging_syslog_facility',
 127     type=str,
 128     default='USER',
 129     choices=[
 130         'NOTSET',
 131         'AUTH',
 132         'AUTH_PRIV',
 133         'CRON',
 134         'DAEMON',
 135         'FTP',
 136         'KERN',
 137         'LPR',
 138         'MAIL',
 139         'NEWS',
 140         'SYSLOG',
 141         'USER',
 142         'UUCP',
 143         'LOCAL0',
 144         'LOCAL1',
 145         'LOCAL2',
 146         'LOCAL3',
 147         'LOCAL4',
 148         'LOCAL5',
 149         'LOCAL6',
 150         'LOCAL7',
 151     ],
 152     metavar='SYSLOG_FACILITY_LIST',
 153     help='The default syslog message facility identifier',
 154 )
 155 cfg.add_argument(
 156     '--logging_debug_threads',
 157     action=argparse_utils.ActionNoYes,
 158     default=False,
 159     help='Should we prepend pid/tid data to all log messages?',
 160 )
 161 cfg.add_argument(
 162     '--logging_debug_modules',
 163     action=argparse_utils.ActionNoYes,
 164     default=False,
 165     help='Should we prepend module/function data to all log messages?',
 166 )
 167 cfg.add_argument(
 168     '--logging_info_is_print',
 169     action=argparse_utils.ActionNoYes,
 170     default=False,
 171     help='logging.info also prints to stdout.',
 172 )
 173 cfg.add_argument(
 174     '--logging_squelch_repeats',
 175     action=argparse_utils.ActionNoYes,
 176     default=True,
 177     help='Do we allow code to indicate that it wants to squelch repeated logging messages or should we always log?',
 178 )
 179 cfg.add_argument(
 180     '--logging_probabilistically',
 181     action=argparse_utils.ActionNoYes,
 182     default=True,
 183     help='Do we allow probabilistic logging (for code that wants it) or should we always log?',
 184 )
 185 # See also: OutputMultiplexer
 186 cfg.add_argument(
 187     '--logging_captures_prints',
 188     action=argparse_utils.ActionNoYes,
 189     default=False,
 190     help='When calling print, also log.info automatically.',
 191 )
 192 cfg.add_argument(
 193     '--lmodule',
 194     type=str,
 195     metavar='<SCOPE>=<LEVEL>[,<SCOPE>=<LEVEL>...]',
 196     help=(
 197         'Allows per-scope logging levels which override the global level set with --logging-level.'
 198         + 'Pass a space separated list of <scope>=<level> where <scope> is one of: module, '
 199         + 'module:function, or :function and <level> is a logging level (e.g. INFO, DEBUG...)'
 200     ),
 201 )
 202 cfg.add_argument(
 203     '--logging_clear_preexisting_handlers',
 204     action=argparse_utils.ActionNoYes,
 205     default=True,
 206     help=(
 207         'Should logging code clear preexisting global logging handlers and thus insist that is '
 208         + 'alone can add handlers.  Use this to work around annoying modules that insert global '
 209         + 'handlers with formats and logging levels you might now want.  Caveat emptor, this may '
 210         + 'cause you to miss logging messages.'
 211     ),
 212 )
 213
 214 BUILT_IN_PRINT = print
 215 LOGGING_INITIALIZED = False
 216
 217
 218 # A map from logging_callsite_id -> count of logged messages.
 219 squelched_logging_counts: Dict[str, int] = {}
 220
 221
 222 def squelch_repeated_log_messages(squelch_after_n_repeats: int) -> Callable:
 223     """
 224     A decorator that marks a function as interested in having the logging
 225     messages that it produces be squelched (ignored) after it logs the
 226     same message more than N times.
 227
 228     .. note::
 229
 230         This decorator affects *ALL* logging messages produced
 231         within the decorated function.  That said, messages must be
 232         identical in order to be squelched.  For example, if the same line
 233         of code produces different messages (because of, e.g., a format
 234         string), the messages are considered to be different.
 235
 236     An example of this from the pyutils code itself can be found in
 237     :meth:`pyutils.ansi.fg` and :meth:`pyutils.ansi.bg` methods::
 238
 239         @logging_utils.squelch_repeated_log_messages(1)
 240         def fg(
 241             name: Optional[str] = "",
 242             red: Optional[int] = None,
 243             green: Optional[int] = None,
 244             blue: Optional[int] = None,
 245             *,
 246             force_16color: bool = False,
 247             force_216color: bool = False,
 248         ) -> str:
 249             ...
 250
 251     These methods log stuff like "Using 24-bit color strategy" which
 252     gets old really fast and fills up the logs.  By decorating the methods
 253     with :code:`@logging_utils.squelch_repeated_log_messages(1)` the code
 254     is requesting that its logged messages be dropped silently after the
 255     first one is produced (note the argument 1).
 256
 257     Users can insist that all logged messages always be reflected in the
 258     logs using the :code:`--no_logging_squelch_repeats` flag but the default
 259     behavior is to allow code to request it be squelched.
 260
 261     :code:`--logging_squelch_repeats` only affects code with this decorator
 262     on it; it ignores all other code.
 263
 264     Args:
 265         squelch_after_n_repeats: the number of repeated messages allowed to
 266             log before subsequent messages are silently dropped.
 267     """
 268
 269     def squelch_logging_wrapper(f: Callable):
 270         from pyutils import function_utils
 271
 272         identifier = function_utils.function_identifier(f)
 273         squelched_logging_counts[identifier] = squelch_after_n_repeats
 274         return f
 275
 276     return squelch_logging_wrapper
 277
 278
 279 class SquelchRepeatedMessagesFilter(logging.Filter):
 280     """A filter that only logs messages from a given site with the same
 281     (exact) message at the same logging level N times and ignores
 282     subsequent attempts to log.
 283
 284     This filter only affects logging messages that repeat more than a
 285     threshold number of times from functions that are tagged with the
 286     :code:`@logging_utils.squelched_logging_ok` decorator (see above);
 287     all others are ignored.
 288
 289     This functionality is enabled by default but can be disabled via
 290     the :code:`--no_logging_squelch_repeats` commandline flag.
 291     """
 292
 293     def __init__(self) -> None:
 294         super().__init__()
 295         self.counters: collections.Counter = collections.Counter()
 296
 297     @overrides
 298     def filter(self, record: logging.LogRecord) -> bool:
 299         """Should we drop this log message?"""
 300         id1 = f'{record.module}:{record.funcName}'
 301         if id1 not in squelched_logging_counts:
 302             return True
 303         threshold = squelched_logging_counts[id1]
 304         logsite = f'{record.pathname}+{record.lineno}+{record.levelno}+{record.msg}'
 305         count = self.counters[logsite]
 306         self.counters[logsite] += 1
 307         return count < threshold
 308
 309
 310 class DynamicPerScopeLoggingLevelFilter(logging.Filter):
 311     """This filter only allows logging messages from an allow list of
 312     module names or `module:function` names.  Blocks all others.  This
 313     filter is used to implement the :code:`--lmodule` commandline option.
 314
 315     .. note::
 316
 317         You probably don't need to use this directly, just use
 318         :code:`--lmodule`.  For example, to set logging level to INFO
 319         everywhere except "module:function" where it should be DEBUG::
 320
 321             # myprogram.py --logging_level=INFO --lmodule=module:function=DEBUG
 322
 323     """
 324
 325     @staticmethod
 326     def level_name_to_level(name: str) -> int:
 327         """Given a level name, return its numberic value."""
 328         numeric_level = getattr(logging, name, None)
 329         if not isinstance(numeric_level, int):
 330             raise ValueError(f'Invalid level: {name}')
 331         return numeric_level
 332
 333     def __init__(
 334         self,
 335         default_logging_level: int,
 336         per_scope_logging_levels: Optional[str],
 337     ) -> None:
 338         """Construct the Filter.
 339
 340         Args:
 341             default_logging_level: the logging level of the whole program
 342             per_scope_logging_levels: optional, comma separated overrides of
 343                 logging level per scope of the format scope=level where
 344                 scope is of the form "module:function" or ":function" and
 345                 level is one of NOTSET, DEBUG, INFO, WARNING, ERROR or
 346                 CRITICAL.
 347         """
 348         super().__init__()
 349         self.valid_levels = set(
 350             ['NOTSET', 'DEBUG', 'INFO', 'WARNING', 'ERROR', 'CRITICAL']
 351         )
 352         self.default_logging_level = default_logging_level
 353         self.level_by_scope = {}
 354         if per_scope_logging_levels is not None:
 355             for chunk in per_scope_logging_levels.split(','):
 356                 if '=' not in chunk:
 357                     print(
 358                         f'Malformed lmodule directive: "{chunk}", missing "=".  Ignored.',
 359                         file=sys.stderr,
 360                     )
 361                     continue
 362                 try:
 363                     (scope, level) = chunk.split('=')
 364                 except ValueError:
 365                     print(
 366                         f'Malformed lmodule directive: "{chunk}".  Ignored.',
 367                         file=sys.stderr,
 368                     )
 369                     continue
 370                 scope = scope.strip()
 371                 level = level.strip().upper()
 372                 if level not in self.valid_levels:
 373                     print(
 374                         f'Malformed lmodule directive: "{chunk}", bad level.  Ignored.',
 375                         file=sys.stderr,
 376                     )
 377                     continue
 378                 self.level_by_scope[
 379                     scope
 380                 ] = DynamicPerScopeLoggingLevelFilter.level_name_to_level(level)
 381
 382     @overrides
 383     def filter(self, record: logging.LogRecord) -> bool:
 384         """Decides whether or not to log based on an allow list."""
 385
 386         # First try to find a logging level by scope (--lmodule)
 387         if len(self.level_by_scope) > 0:
 388             min_level = None
 389             for scope in (
 390                 record.module,
 391                 f'{record.module}:{record.funcName}',
 392                 f':{record.funcName}',
 393             ):
 394                 level = self.level_by_scope.get(scope, None)
 395                 if level is not None:
 396                     if min_level is None or level < min_level:
 397                         min_level = level
 398
 399             # If we found one, use it instead of the global default level.
 400             if min_level is not None:
 401                 return record.levelno >= min_level
 402
 403         # Otherwise, use the global logging level (--logging_level)
 404         return record.levelno >= self.default_logging_level
 405
 406
 407 # A map from function_identifier -> probability of logging (0.0%..100.0%)
 408 probabilistic_logging_levels: Dict[str, float] = {}
 409
 410
 411 def logging_is_probabilistic(probability_of_logging: float) -> Callable:
 412     """A decorator that indicates that all logging statements within the
 413     scope of a particular (marked via decorator) function are not
 414     deterministic (i.e. they do not always unconditionally log) but rather
 415     are probabilistic (i.e. they log N% of the time, randomly) when the
 416     user passes the :code:`--logging_probabilistically` commandline flag
 417     (which is enabled by default).
 418
 419     .. note::
 420
 421         This affects *ALL* logging statements within the marked function.
 422         If you want it to only affect a subset of logging statements,
 423         log those statements in a separate function that you invoke
 424         from within the "too large" scope and mark that separate function
 425         with the :code:`logging_is_probabilistic` decorator instead.
 426
 427     That this functionality can be disabled (forcing all logged
 428     messages to produce output) via the
 429     :code:`--no_logging_probabilistically` cmdline argument.
 430     """
 431
 432     def probabilistic_logging_wrapper(f: Callable):
 433         from pyutils import function_utils
 434
 435         identifier = function_utils.function_identifier(f)
 436         probabilistic_logging_levels[identifier] = probability_of_logging
 437         return f
 438
 439     return probabilistic_logging_wrapper
 440
 441
 442 class ProbabilisticFilter(logging.Filter):
 443     """
 444     A filter that logs messages probabilistically (i.e. randomly at some
 445     percent chance).  This filter is used with a decorator (see
 446     :meth:`logging_is_probabilistic`) to implement the
 447     :code:`--logging_probabilistically` commandline flag.
 448
 449     This filter only affects logging messages from functions that have
 450     been tagged with the `@logging_utils.probabilistic_logging` decorator.
 451     """
 452
 453     @overrides
 454     def filter(self, record: logging.LogRecord) -> bool:
 455         """Should the message be logged?"""
 456         id1 = f'{record.module}:{record.funcName}'
 457         if id1 not in probabilistic_logging_levels:
 458             return True
 459         threshold = probabilistic_logging_levels[id1]
 460         return (random.random() * 100.0) <= threshold
 461
 462
 463 class OnlyInfoFilter(logging.Filter):
 464     """A filter that only logs messages produced at the INFO logging
 465     level.  This is used by the :code:`--logging_info_is_print`
 466     commandline option to select a subset of the logging stream to
 467     send to a stdout handler.
 468     """
 469
 470     @overrides
 471     def filter(self, record: logging.LogRecord):
 472         return record.levelno == logging.INFO
 473
 474
 475 class MillisecondAwareFormatter(logging.Formatter):
 476     """
 477     A formatter for adding milliseconds to log messages which, for
 478     whatever reason, the default Python logger doesn't do.
 479
 480     .. note::
 481
 482         You probably don't need to use this directly but it is
 483         wired in under :meth:initialize_logging so that the
 484         timestamps in log messages have millisecond level
 485         precision.
 486     """
 487
 488     converter = datetime.datetime.fromtimestamp  # type: ignore
 489
 490     @overrides
 491     def formatTime(self, record, datefmt=None):
 492         ct = MillisecondAwareFormatter.converter(
 493             record.created, pytz.timezone("US/Pacific")
 494         )
 495         if datefmt:
 496             s = ct.strftime(datefmt)
 497         else:
 498             t = ct.strftime("%Y-%m-%d %H:%M:%S")
 499             s = f"{t},{record.msecs:%03d}"
 500         return s
 501
 502
 503 def _log_about_logging(
 504     logger,
 505     default_logging_level,
 506     preexisting_handlers_count,
 507     fmt,
 508     facility_name,
 509 ):
 510     """This is invoked automatically after logging is initialized such
 511     that the first messages in the log are about how logging itself
 512     was configured.
 513     """
 514     level_name = logging._levelToName.get(
 515         default_logging_level, str(default_logging_level)
 516     )
 517     logger.debug('Initialized global logging; default logging level is %s.', level_name)
 518     if (
 519         config.config['logging_clear_preexisting_handlers']
 520         and preexisting_handlers_count > 0
 521     ):
 522         logger.debug(
 523             'Logging cleared %d global handlers (--logging_clear_preexisting_handlers)',
 524             preexisting_handlers_count,
 525         )
 526     logger.debug('Logging format specification is "%s"', fmt)
 527     if config.config['logging_debug_threads']:
 528         logger.debug(
 529             '...Logging format spec captures tid/pid. (--logging_debug_threads)'
 530         )
 531     if config.config['logging_debug_modules']:
 532         logger.debug(
 533             '...Logging format spec captures files/functions/lineno. (--logging_debug_modules)'
 534         )
 535     if config.config['logging_syslog']:
 536         logger.debug(
 537             'Logging to syslog as %s with priority mapping based on level. (--logging_syslog)',
 538             facility_name,
 539         )
 540     if config.config['logging_filename']:
 541         logger.debug(
 542             'Logging to file "%s". (--logging_filename)',
 543             config.config["logging_filename"],
 544         )
 545         logger.debug(
 546             '...with %d bytes max file size. (--logging_filename_maxsize)',
 547             config.config["logging_filename_maxsize"],
 548         )
 549         logger.debug(
 550             '...and %d rotating backup file count. (--logging_filename_count)',
 551             config.config["logging_filename_count"],
 552         )
 553     if config.config['logging_console']:
 554         logger.debug('Logging to the console (stderr). (--logging_console)')
 555     if config.config['logging_info_is_print']:
 556         logger.debug(
 557             'Logging logger.info messages will be repeated on stdout. (--logging_info_is_print)'
 558         )
 559     if config.config['logging_squelch_repeats']:
 560         logger.debug(
 561             'Logging code allowed to request repeated messages be squelched. (--logging_squelch_repeats)'
 562         )
 563     else:
 564         logger.debug(
 565             'Logging code forbidden to request messages be squelched; all messages logged. (--no_logging_squelch_repeats)'
 566         )
 567     if config.config['logging_probabilistically']:
 568         logger.debug(
 569             'Logging code is allowed to request probabilistic logging. (--logging_probabilistically)'
 570         )
 571     else:
 572         logger.debug(
 573             'Logging code is forbidden to request probabilistic logging; messages always logged. (--no_logging_probabilistically)'
 574         )
 575     if config.config['lmodule']:
 576         logger.debug(
 577             f'Logging dynamic per-module logging enabled. (--lmodule={config.config["lmodule"]})'
 578         )
 579     if config.config['logging_captures_prints']:
 580         logger.debug(
 581             'Logging will capture printed data as logger.info messages. (--logging_captures_prints)'
 582         )
 583
 584
 585 def initialize_logging(logger=None) -> logging.Logger:
 586     """Initialize logging for the program.  See module level comments
 587     for information about what functionality this provides and how to
 588     enable or disable functionality via the commandline.
 589
 590     If you use the
 591     :meth:`bootstrap.initialize` decorator on your program's entry point,
 592     it will call this for you.  See :meth:`pyutils.bootstrap.initialize`
 593     for more details.
 594     """
 595     global LOGGING_INITIALIZED
 596     if LOGGING_INITIALIZED:
 597         return logging.getLogger()
 598     LOGGING_INITIALIZED = True
 599
 600     if logger is None:
 601         logger = logging.getLogger()
 602
 603     # --logging_clear_preexisting_handlers removes logging handlers
 604     # that were registered by global statements during imported module
 605     # setup.
 606     preexisting_handlers_count = 0
 607     assert config.has_been_parsed()
 608     if config.config['logging_clear_preexisting_handlers']:
 609         while logger.hasHandlers():
 610             logger.removeHandler(logger.handlers[0])
 611             preexisting_handlers_count += 1
 612
 613     # --logging_config_file pulls logging settings from a config file
 614     # skipping the rest of this setup.
 615     if config.config['logging_config_file'] is not None:
 616         fileConfig(config.config['logging_config_file'])
 617         return logger
 618
 619     handlers: List[logging.Handler] = []
 620     handler: Optional[logging.Handler] = None
 621
 622     # Global default logging level (--logging_level); messages below
 623     # this level will be silenced.
 624     logging_level = config.config['logging_level']
 625     assert logging_level
 626     logging_level = logging_level.upper()
 627     default_logging_level = getattr(logging, logging_level, None)
 628     if not isinstance(default_logging_level, int):
 629         raise ValueError(f'Invalid level: {config.config["logging_level"]}')
 630
 631     # Custom or default --logging_format?
 632     if config.config['logging_format']:
 633         fmt = config.config['logging_format']
 634     else:
 635         if config.config['logging_syslog']:
 636             fmt = '%(levelname).1s:%(filename)s[%(process)d]: %(message)s'
 637         else:
 638             fmt = '%(levelname).1s:%(asctime)s: %(message)s'
 639
 640     # --logging_debug_threads and --logging_debug_modules both affect
 641     # the format by prepending information about the pid/tid or
 642     # file/function.
 643     if config.config['logging_debug_threads']:
 644         fmt = f'%(process)d.%(thread)d|{fmt}'
 645     if config.config['logging_debug_modules']:
 646         fmt = f'%(filename)s:%(funcName)s:%(lineno)s|{fmt}'
 647
 648     # --logging_syslog (optionally with --logging_syslog_facility)
 649     # sets up for logging to use the standard system syslogd as a
 650     # sink.
 651     facility_name = None
 652     if config.config['logging_syslog']:
 653         if sys.platform not in ('win32', 'cygwin'):
 654             if config.config['logging_syslog_facility']:
 655                 facility_name = 'LOG_' + config.config['logging_syslog_facility']
 656             facility = SysLogHandler.__dict__.get(facility_name, SysLogHandler.LOG_USER)  # type: ignore
 657             assert facility is not None
 658             handler = SysLogHandler(facility=facility, address='/dev/log')
 659             handler.setFormatter(
 660                 MillisecondAwareFormatter(
 661                     fmt=fmt,
 662                     datefmt=config.config['logging_date_format'],
 663                 )
 664             )
 665             handlers.append(handler)
 666
 667     # --logging_filename (with friends --logging_filename_count and
 668     # --logging_filename_maxsize) set up logging to a file on the
 669     # filesystem with automatic rotation when it gets too big.
 670     if config.config['logging_filename']:
 671         max_bytes = config.config['logging_filename_maxsize']
 672         assert max_bytes and type(max_bytes) == int
 673         backup_count = config.config['logging_filename_count']
 674         assert backup_count and type(backup_count) == int
 675         handler = RotatingFileHandler(
 676             config.config['logging_filename'],
 677             maxBytes=max_bytes,
 678             backupCount=backup_count,
 679         )
 680         handler.setFormatter(
 681             MillisecondAwareFormatter(
 682                 fmt=fmt,
 683                 datefmt=config.config['logging_date_format'],
 684             )
 685         )
 686         handlers.append(handler)
 687
 688     # --logging_console is, ahem, logging to the console.
 689     if config.config['logging_console']:
 690         handler = logging.StreamHandler(sys.stderr)
 691         handler.setFormatter(
 692             MillisecondAwareFormatter(
 693                 fmt=fmt,
 694                 datefmt=config.config['logging_date_format'],
 695             )
 696         )
 697         handlers.append(handler)
 698
 699     if len(handlers) == 0:
 700         handlers.append(logging.NullHandler())
 701     for handler in handlers:
 702         logger.addHandler(handler)
 703
 704     # --logging_info_is_print echoes any message to logger.info(x) as
 705     # a print statement on stdout.
 706     if config.config['logging_info_is_print']:
 707         handler = logging.StreamHandler(sys.stdout)
 708         handler.addFilter(OnlyInfoFilter())
 709         logger.addHandler(handler)
 710
 711     # --logging_squelch_repeats allows code to request repeat logging
 712     # messages (identical log site and message contents) to be
 713     # silenced.  Logging code must request this explicitly, it isn't
 714     # automatic.  This option just allows the silencing to happen.
 715     if config.config['logging_squelch_repeats']:
 716         for handler in handlers:
 717             handler.addFilter(SquelchRepeatedMessagesFilter())
 718
 719     # --logging_probabilistically allows code to request
 720     # non-deterministic logging where messages have some probability
 721     # of being produced.  Logging code must request this explicitly.
 722     # This option just allows the non-deterministic behavior to
 723     # happen.  Disabling it will cause every log message to be
 724     # produced.
 725     if config.config['logging_probabilistically']:
 726         for handler in handlers:
 727             handler.addFilter(ProbabilisticFilter())
 728
 729     # --lmodule is a way to have a special logging level for just on
 730     # module or one set of modules that is different than the one set
 731     # globally via --logging_level.
 732     for handler in handlers:
 733         handler.addFilter(
 734             DynamicPerScopeLoggingLevelFilter(
 735                 default_logging_level,
 736                 config.config['lmodule'],
 737             )
 738         )
 739     logger.setLevel(0)
 740     logger.propagate = False
 741
 742     # --logging_captures_prints, if set, will capture and log.info
 743     # anything printed on stdout.
 744     if config.config['logging_captures_prints']:
 745         import builtins
 746
 747         def print_and_also_log(*arg, **kwarg):
 748             f = kwarg.get('file', None)
 749             if f == sys.stderr:
 750                 logger.warning(*arg)
 751             else:
 752                 logger.info(*arg)
 753             BUILT_IN_PRINT(*arg, **kwarg)
 754
 755         builtins.print = print_and_also_log
 756
 757     # At this point the logger is ready, handlers are set up,
 758     # etc... so log about the logging configuration.
 759     _log_about_logging(
 760         logger,
 761         default_logging_level,
 762         preexisting_handlers_count,
 763         fmt,
 764         facility_name,
 765     )
 766     return logger
 767
 768
 769 def get_logger(name: str = ""):
 770     """Get the global logger"""
 771     logger = logging.getLogger(name)
 772     return initialize_logging(logger)
 773
 774
 775 def tprint(*args, **kwargs) -> None:
 776     """Legacy function for printing a message augmented with thread id
 777     still needed by some code.  Please use --logging_debug_threads in
 778     new code.
 779     """
 780     if config.config['logging_debug_threads']:
 781         from pyutils.parallelize.thread_utils import current_thread_id
 782
 783         print(f'{current_thread_id()}', end="")
 784         print(*args, **kwargs)
 785     else:
 786         pass
 787
 788
 789 class OutputMultiplexer(object):
 790     """A class that broadcasts printed messages to several sinks
 791     (including various logging levels, different files, different file
 792     handles, the house log, etc...).  See also
 793     :class:`OutputMultiplexerContext` for an easy usage pattern.
 794     """
 795
 796     class Destination(enum.IntEnum):
 797         """Bits in the destination_bitv bitvector.  Used to indicate the
 798         output destination."""
 799
 800         # fmt: off
 801         LOG_DEBUG = 0x01     #  ⎫
 802         LOG_INFO = 0x02      #  ⎪
 803         LOG_WARNING = 0x04   #  ⎬ Must provide logger to the c'tor.
 804         LOG_ERROR = 0x08     #  ⎪
 805         LOG_CRITICAL = 0x10  #  ⎭
 806         FILENAMES = 0x20     # Must provide a filename to the c'tor.
 807         FILEHANDLES = 0x40   # Must provide a handle to the c'tor.
 808         HLOG = 0x80
 809         ALL_LOG_DESTINATIONS = (
 810             LOG_DEBUG | LOG_INFO | LOG_WARNING | LOG_ERROR | LOG_CRITICAL
 811         )
 812         ALL_OUTPUT_DESTINATIONS = 0x8F
 813         # fmt: on
 814
 815     def __init__(
 816         self,
 817         destination_bitv: int,
 818         *,
 819         logger=None,
 820         filenames: Optional[Iterable[str]] = None,
 821         handles: Optional[Iterable[io.TextIOWrapper]] = None,
 822     ):
 823         """
 824         Constructs the OutputMultiplexer instance.
 825
 826         Args:
 827             destination_bitv: a bitvector where each bit represents an
 828                 output destination.  Multiple bits may be set.
 829             logger: if LOG_* bits are set, you must pass a logger here.
 830             filenames: if FILENAMES bit is set, this should be a list of
 831                 files you'd like to output into.  This code handles opening
 832                 and closing said files.
 833             handles: if FILEHANDLES bit is set, this should be a list of
 834                 already opened filehandles you'd like to output into.  The
 835                 handles will remain open after the scope of the multiplexer.
 836         """
 837         if logger is None:
 838             logger = logging.getLogger(None)
 839         self.logger = logger
 840
 841         self.f: Optional[List[Any]] = None
 842         if filenames is not None:
 843             self.f = [open(filename, 'wb', buffering=0) for filename in filenames]
 844         else:
 845             if destination_bitv & OutputMultiplexer.Destination.FILENAMES:
 846                 raise ValueError("Filenames argument is required if bitv & FILENAMES")
 847             self.f = None
 848
 849         self.h: Optional[List[Any]] = None
 850         if handles is not None:
 851             self.h = list(handles)
 852         else:
 853             if destination_bitv & OutputMultiplexer.Destination.FILEHANDLES:
 854                 raise ValueError("Handle argument is required if bitv & FILEHANDLES")
 855             self.h = None
 856
 857         self.set_destination_bitv(destination_bitv)
 858
 859     def get_destination_bitv(self):
 860         """Where are we outputting?"""
 861         return self.destination_bitv
 862
 863     def set_destination_bitv(self, destination_bitv: int):
 864         """Change the output destination_bitv to the one provided."""
 865         if destination_bitv & self.Destination.FILENAMES and self.f is None:
 866             raise ValueError("Filename argument is required if bitv & FILENAMES")
 867         if destination_bitv & self.Destination.FILEHANDLES and self.h is None:
 868             raise ValueError("Handle argument is required if bitv & FILEHANDLES")
 869         self.destination_bitv = destination_bitv
 870
 871     def print(self, *args, **kwargs):
 872         """Produce some output to all sinks."""
 873         from pyutils.string_utils import _sprintf, strip_escape_sequences
 874
 875         end = kwargs.pop("end", None)
 876         if end is not None:
 877             if not isinstance(end, str):
 878                 raise TypeError("end must be None or a string")
 879         sep = kwargs.pop("sep", None)
 880         if sep is not None:
 881             if not isinstance(sep, str):
 882                 raise TypeError("sep must be None or a string")
 883         if kwargs:
 884             raise TypeError("invalid keyword arguments to print()")
 885         buf = _sprintf(*args, end="", sep=sep)
 886         if sep is None:
 887             sep = " "
 888         if end is None:
 889             end = "\n"
 890         if end == '\n':
 891             buf += '\n'
 892         if self.destination_bitv & self.Destination.FILENAMES and self.f is not None:
 893             for _ in self.f:
 894                 _.write(buf.encode('utf-8'))
 895                 _.flush()
 896
 897         if self.destination_bitv & self.Destination.FILEHANDLES and self.h is not None:
 898             for _ in self.h:
 899                 _.write(buf)
 900                 _.flush()
 901
 902         buf = strip_escape_sequences(buf)
 903         if self.logger is not None:
 904             if self.destination_bitv & self.Destination.LOG_DEBUG:
 905                 self.logger.debug(buf)
 906             if self.destination_bitv & self.Destination.LOG_INFO:
 907                 self.logger.info(buf)
 908             if self.destination_bitv & self.Destination.LOG_WARNING:
 909                 self.logger.warning(buf)
 910             if self.destination_bitv & self.Destination.LOG_ERROR:
 911                 self.logger.error(buf)
 912             if self.destination_bitv & self.Destination.LOG_CRITICAL:
 913                 self.logger.critical(buf)
 914         if self.destination_bitv & self.Destination.HLOG:
 915             hlog(buf)
 916
 917     def close(self):
 918         """Close all open files."""
 919         if self.f is not None:
 920             for _ in self.f:
 921                 _.close()
 922
 923
 924 class OutputMultiplexerContext(OutputMultiplexer, contextlib.ContextDecorator):
 925     """
 926     A context that uses an :class:`OutputMultiplexer`.  e.g.::
 927
 928         with OutputMultiplexerContext(
 929                 OutputMultiplexer.LOG_INFO |
 930                 OutputMultiplexer.LOG_DEBUG |
 931                 OutputMultiplexer.FILENAMES |
 932                 OutputMultiplexer.FILEHANDLES,
 933                 filenames = [ '/tmp/foo.log', '/var/log/bar.log' ],
 934                 handles = [ f, g ]
 935             ) as mplex:
 936                 mplex.print("This is a log message!")
 937     """
 938
 939     def __init__(
 940         self,
 941         destination_bitv: OutputMultiplexer.Destination,
 942         *,
 943         logger=None,
 944         filenames=None,
 945         handles=None,
 946     ):
 947         """
 948         Args:
 949             destination_bitv: a bitvector that indicates where we should
 950                 send output.  See :class:`OutputMultiplexer` for options.
 951             logger: optional logger to use for log destination messages.
 952             filenames: optional filenames to write for filename destination
 953                 messages.
 954             handles: optional open filehandles to write for filehandle
 955                 destination messages.
 956         """
 957         super().__init__(
 958             destination_bitv,
 959             logger=logger,
 960             filenames=filenames,
 961             handles=handles,
 962         )
 963
 964     def __enter__(self):
 965         return self
 966
 967     def __exit__(self, etype, value, traceback) -> bool:
 968         super().close()
 969         if etype is not None:
 970             return False
 971         return True
 972
 973
 974 def hlog(message: str) -> None:
 975     """Write a message to the house log (syslog facility local7 priority
 976     info) by calling `/usr/bin/logger`.  This is pretty hacky but used
 977     by a bunch of (my) code.  Another way to do this would be to use
 978     :code:`--logging_syslog` and :code:`--logging_syslog_facility` but
 979     I can't actually say that's easier.
 980
 981     TODO: this needs to move.
 982     """
 983     message = message.replace("'", "'\"'\"'")
 984     os.system(f"/usr/bin/logger -p local7.info -- '{message}'")
 985
 986
 987 if __name__ == '__main__':
 988     import doctest
 989
 990     doctest.testmod()