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     default_logging_level = getattr(
 625         logging, config.config['logging_level'].upper(), None
 626     )
 627     if not isinstance(default_logging_level, int):
 628         raise ValueError(f'Invalid level: {config.config["logging_level"]}')
 629
 630     # Custom or default --logging_format?
 631     if config.config['logging_format']:
 632         fmt = config.config['logging_format']
 633     else:
 634         if config.config['logging_syslog']:
 635             fmt = '%(levelname).1s:%(filename)s[%(process)d]: %(message)s'
 636         else:
 637             fmt = '%(levelname).1s:%(asctime)s: %(message)s'
 638
 639     # --logging_debug_threads and --logging_debug_modules both affect
 640     # the format by prepending information about the pid/tid or
 641     # file/function.
 642     if config.config['logging_debug_threads']:
 643         fmt = f'%(process)d.%(thread)d|{fmt}'
 644     if config.config['logging_debug_modules']:
 645         fmt = f'%(filename)s:%(funcName)s:%(lineno)s|{fmt}'
 646
 647     # --logging_syslog (optionally with --logging_syslog_facility)
 648     # sets up for logging to use the standard system syslogd as a
 649     # sink.
 650     facility_name = None
 651     if config.config['logging_syslog']:
 652         if sys.platform not in ('win32', 'cygwin'):
 653             if config.config['logging_syslog_facility']:
 654                 facility_name = 'LOG_' + config.config['logging_syslog_facility']
 655             facility = SysLogHandler.__dict__.get(facility_name, SysLogHandler.LOG_USER)  # type: ignore
 656             assert facility is not None
 657             handler = SysLogHandler(facility=facility, address='/dev/log')
 658             handler.setFormatter(
 659                 MillisecondAwareFormatter(
 660                     fmt=fmt,
 661                     datefmt=config.config['logging_date_format'],
 662                 )
 663             )
 664             handlers.append(handler)
 665
 666     # --logging_filename (with friends --logging_filename_count and
 667     # --logging_filename_maxsize) set up logging to a file on the
 668     # filesystem with automatic rotation when it gets too big.
 669     if config.config['logging_filename']:
 670         handler = RotatingFileHandler(
 671             config.config['logging_filename'],
 672             maxBytes=config.config['logging_filename_maxsize'],
 673             backupCount=config.config['logging_filename_count'],
 674         )
 675         handler.setFormatter(
 676             MillisecondAwareFormatter(
 677                 fmt=fmt,
 678                 datefmt=config.config['logging_date_format'],
 679             )
 680         )
 681         handlers.append(handler)
 682
 683     # --logging_console is, ahem, logging to the console.
 684     if config.config['logging_console']:
 685         handler = logging.StreamHandler(sys.stderr)
 686         handler.setFormatter(
 687             MillisecondAwareFormatter(
 688                 fmt=fmt,
 689                 datefmt=config.config['logging_date_format'],
 690             )
 691         )
 692         handlers.append(handler)
 693
 694     if len(handlers) == 0:
 695         handlers.append(logging.NullHandler())
 696     for handler in handlers:
 697         logger.addHandler(handler)
 698
 699     # --logging_info_is_print echoes any message to logger.info(x) as
 700     # a print statement on stdout.
 701     if config.config['logging_info_is_print']:
 702         handler = logging.StreamHandler(sys.stdout)
 703         handler.addFilter(OnlyInfoFilter())
 704         logger.addHandler(handler)
 705
 706     # --logging_squelch_repeats allows code to request repeat logging
 707     # messages (identical log site and message contents) to be
 708     # silenced.  Logging code must request this explicitly, it isn't
 709     # automatic.  This option just allows the silencing to happen.
 710     if config.config['logging_squelch_repeats']:
 711         for handler in handlers:
 712             handler.addFilter(SquelchRepeatedMessagesFilter())
 713
 714     # --logging_probabilistically allows code to request
 715     # non-deterministic logging where messages have some probability
 716     # of being produced.  Logging code must request this explicitly.
 717     # This option just allows the non-deterministic behavior to
 718     # happen.  Disabling it will cause every log message to be
 719     # produced.
 720     if config.config['logging_probabilistically']:
 721         for handler in handlers:
 722             handler.addFilter(ProbabilisticFilter())
 723
 724     # --lmodule is a way to have a special logging level for just on
 725     # module or one set of modules that is different than the one set
 726     # globally via --logging_level.
 727     for handler in handlers:
 728         handler.addFilter(
 729             DynamicPerScopeLoggingLevelFilter(
 730                 default_logging_level,
 731                 config.config['lmodule'],
 732             )
 733         )
 734     logger.setLevel(0)
 735     logger.propagate = False
 736
 737     # --logging_captures_prints, if set, will capture and log.info
 738     # anything printed on stdout.
 739     if config.config['logging_captures_prints']:
 740         import builtins
 741
 742         def print_and_also_log(*arg, **kwarg):
 743             f = kwarg.get('file', None)
 744             if f == sys.stderr:
 745                 logger.warning(*arg)
 746             else:
 747                 logger.info(*arg)
 748             BUILT_IN_PRINT(*arg, **kwarg)
 749
 750         builtins.print = print_and_also_log
 751
 752     # At this point the logger is ready, handlers are set up,
 753     # etc... so log about the logging configuration.
 754     _log_about_logging(
 755         logger,
 756         default_logging_level,
 757         preexisting_handlers_count,
 758         fmt,
 759         facility_name,
 760     )
 761     return logger
 762
 763
 764 def get_logger(name: str = ""):
 765     """Get the global logger"""
 766     logger = logging.getLogger(name)
 767     return initialize_logging(logger)
 768
 769
 770 def tprint(*args, **kwargs) -> None:
 771     """Legacy function for printing a message augmented with thread id
 772     still needed by some code.  Please use --logging_debug_threads in
 773     new code.
 774     """
 775     if config.config['logging_debug_threads']:
 776         from pyutils.parallelize.thread_utils import current_thread_id
 777
 778         print(f'{current_thread_id()}', end="")
 779         print(*args, **kwargs)
 780     else:
 781         pass
 782
 783
 784 class OutputMultiplexer(object):
 785     """A class that broadcasts printed messages to several sinks
 786     (including various logging levels, different files, different file
 787     handles, the house log, etc...).  See also
 788     :class:`OutputMultiplexerContext` for an easy usage pattern.
 789     """
 790
 791     class Destination(enum.IntEnum):
 792         """Bits in the destination_bitv bitvector.  Used to indicate the
 793         output destination."""
 794
 795         # fmt: off
 796         LOG_DEBUG = 0x01     #  ⎫
 797         LOG_INFO = 0x02      #  ⎪
 798         LOG_WARNING = 0x04   #  ⎬ Must provide logger to the c'tor.
 799         LOG_ERROR = 0x08     #  ⎪
 800         LOG_CRITICAL = 0x10  #  ⎭
 801         FILENAMES = 0x20     # Must provide a filename to the c'tor.
 802         FILEHANDLES = 0x40   # Must provide a handle to the c'tor.
 803         HLOG = 0x80
 804         ALL_LOG_DESTINATIONS = (
 805             LOG_DEBUG | LOG_INFO | LOG_WARNING | LOG_ERROR | LOG_CRITICAL
 806         )
 807         ALL_OUTPUT_DESTINATIONS = 0x8F
 808         # fmt: on
 809
 810     def __init__(
 811         self,
 812         destination_bitv: int,
 813         *,
 814         logger=None,
 815         filenames: Optional[Iterable[str]] = None,
 816         handles: Optional[Iterable[io.TextIOWrapper]] = None,
 817     ):
 818         """
 819         Constructs the OutputMultiplexer instance.
 820
 821         Args:
 822             destination_bitv: a bitvector where each bit represents an
 823                 output destination.  Multiple bits may be set.
 824             logger: if LOG_* bits are set, you must pass a logger here.
 825             filenames: if FILENAMES bit is set, this should be a list of
 826                 files you'd like to output into.  This code handles opening
 827                 and closing said files.
 828             handles: if FILEHANDLES bit is set, this should be a list of
 829                 already opened filehandles you'd like to output into.  The
 830                 handles will remain open after the scope of the multiplexer.
 831         """
 832         if logger is None:
 833             logger = logging.getLogger(None)
 834         self.logger = logger
 835
 836         self.f: Optional[List[Any]] = None
 837         if filenames is not None:
 838             self.f = [open(filename, 'wb', buffering=0) for filename in filenames]
 839         else:
 840             if destination_bitv & OutputMultiplexer.Destination.FILENAMES:
 841                 raise ValueError("Filenames argument is required if bitv & FILENAMES")
 842             self.f = None
 843
 844         self.h: Optional[List[Any]] = None
 845         if handles is not None:
 846             self.h = list(handles)
 847         else:
 848             if destination_bitv & OutputMultiplexer.Destination.FILEHANDLES:
 849                 raise ValueError("Handle argument is required if bitv & FILEHANDLES")
 850             self.h = None
 851
 852         self.set_destination_bitv(destination_bitv)
 853
 854     def get_destination_bitv(self):
 855         """Where are we outputting?"""
 856         return self.destination_bitv
 857
 858     def set_destination_bitv(self, destination_bitv: int):
 859         """Change the output destination_bitv to the one provided."""
 860         if destination_bitv & self.Destination.FILENAMES and self.f is None:
 861             raise ValueError("Filename argument is required if bitv & FILENAMES")
 862         if destination_bitv & self.Destination.FILEHANDLES and self.h is None:
 863             raise ValueError("Handle argument is required if bitv & FILEHANDLES")
 864         self.destination_bitv = destination_bitv
 865
 866     def print(self, *args, **kwargs):
 867         """Produce some output to all sinks."""
 868         from pyutils.string_utils import _sprintf, strip_escape_sequences
 869
 870         end = kwargs.pop("end", None)
 871         if end is not None:
 872             if not isinstance(end, str):
 873                 raise TypeError("end must be None or a string")
 874         sep = kwargs.pop("sep", None)
 875         if sep is not None:
 876             if not isinstance(sep, str):
 877                 raise TypeError("sep must be None or a string")
 878         if kwargs:
 879             raise TypeError("invalid keyword arguments to print()")
 880         buf = _sprintf(*args, end="", sep=sep)
 881         if sep is None:
 882             sep = " "
 883         if end is None:
 884             end = "\n"
 885         if end == '\n':
 886             buf += '\n'
 887         if self.destination_bitv & self.Destination.FILENAMES and self.f is not None:
 888             for _ in self.f:
 889                 _.write(buf.encode('utf-8'))
 890                 _.flush()
 891
 892         if self.destination_bitv & self.Destination.FILEHANDLES and self.h is not None:
 893             for _ in self.h:
 894                 _.write(buf)
 895                 _.flush()
 896
 897         buf = strip_escape_sequences(buf)
 898         if self.logger is not None:
 899             if self.destination_bitv & self.Destination.LOG_DEBUG:
 900                 self.logger.debug(buf)
 901             if self.destination_bitv & self.Destination.LOG_INFO:
 902                 self.logger.info(buf)
 903             if self.destination_bitv & self.Destination.LOG_WARNING:
 904                 self.logger.warning(buf)
 905             if self.destination_bitv & self.Destination.LOG_ERROR:
 906                 self.logger.error(buf)
 907             if self.destination_bitv & self.Destination.LOG_CRITICAL:
 908                 self.logger.critical(buf)
 909         if self.destination_bitv & self.Destination.HLOG:
 910             hlog(buf)
 911
 912     def close(self):
 913         """Close all open files."""
 914         if self.f is not None:
 915             for _ in self.f:
 916                 _.close()
 917
 918
 919 class OutputMultiplexerContext(OutputMultiplexer, contextlib.ContextDecorator):
 920     """
 921     A context that uses an :class:`OutputMultiplexer`.  e.g.::
 922
 923         with OutputMultiplexerContext(
 924                 OutputMultiplexer.LOG_INFO |
 925                 OutputMultiplexer.LOG_DEBUG |
 926                 OutputMultiplexer.FILENAMES |
 927                 OutputMultiplexer.FILEHANDLES,
 928                 filenames = [ '/tmp/foo.log', '/var/log/bar.log' ],
 929                 handles = [ f, g ]
 930             ) as mplex:
 931                 mplex.print("This is a log message!")
 932     """
 933
 934     def __init__(
 935         self,
 936         destination_bitv: OutputMultiplexer.Destination,
 937         *,
 938         logger=None,
 939         filenames=None,
 940         handles=None,
 941     ):
 942         """
 943         Args:
 944             destination_bitv: a bitvector that indicates where we should
 945                 send output.  See :class:`OutputMultiplexer` for options.
 946             logger: optional logger to use for log destination messages.
 947             filenames: optional filenames to write for filename destination
 948                 messages.
 949             handles: optional open filehandles to write for filehandle
 950                 destination messages.
 951         """
 952         super().__init__(
 953             destination_bitv,
 954             logger=logger,
 955             filenames=filenames,
 956             handles=handles,
 957         )
 958
 959     def __enter__(self):
 960         return self
 961
 962     def __exit__(self, etype, value, traceback) -> bool:
 963         super().close()
 964         if etype is not None:
 965             return False
 966         return True
 967
 968
 969 def hlog(message: str) -> None:
 970     """Write a message to the house log (syslog facility local7 priority
 971     info) by calling `/usr/bin/logger`.  This is pretty hacky but used
 972     by a bunch of (my) code.  Another way to do this would be to use
 973     :code:`--logging_syslog` and :code:`--logging_syslog_facility` but
 974     I can't actually say that's easier.
 975
 976     TODO: this needs to move.
 977     """
 978     message = message.replace("'", "'\"'\"'")
 979     os.system(f"/usr/bin/logger -p local7.info -- '{message}'")
 980
 981
 982 if __name__ == '__main__':
 983     import doctest
 984
 985     doctest.testmod()