src/pyutils/logging_utils.py

   1 #!/usr/bin/env python3
   2 # -*- coding: utf-8 -*-
   3
   4 # © Copyright 2021-2023, 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 sys
  51 import threading
  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, misc_utils
  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         identifier = f"{record.module}:{record.funcName}"
 457         threshold = probabilistic_logging_levels.get(identifier, 100.0)
 458         return misc_utils.execute_probabilistically(threshold)
 459
 460
 461 class OnlyInfoFilter(logging.Filter):
 462     """A filter that only logs messages produced at the INFO logging
 463     level.  This is used by the :code:`--logging_info_is_print`
 464     commandline option to select a subset of the logging stream to
 465     send to a stdout handler.
 466     """
 467
 468     @overrides
 469     def filter(self, record: logging.LogRecord):
 470         return record.levelno == logging.INFO
 471
 472
 473 def get_current_pidtid() -> str:
 474     return f"{os.getpid()}/{threading.get_ident()}"
 475
 476
 477 LOGGING_PREFIXES_BY_PIDTID = {}
 478
 479
 480 def register_thread_logging_prefix(message: str) -> None:
 481     """A function that allows a thread to register a string that
 482     should be prepended to every log message it produces from now on.
 483     This overwrites any previous message registered to this thread
 484     and can be called with None or an empty string to clear any
 485     previous message.
 486     """
 487     pidtid = get_current_pidtid()
 488     if message and len(message) > 0:
 489         LOGGING_PREFIXES_BY_PIDTID[pidtid] = message
 490     elif pidtid in LOGGING_PREFIXES_BY_PIDTID:
 491         del LOGGING_PREFIXES_BY_PIDTID[pidtid]
 492
 493
 494 LOGGING_SUFFIXES_BY_PIDTID = {}
 495
 496
 497 def register_thread_logging_suffix(message: str) -> None:
 498     """A function that allows a thread to register a string that
 499     should be appended to every log message it produces from now on.
 500     This overwrites any previous message registered to this thread
 501     and can be called with None or an empty string to clear any
 502     previous message.
 503     """
 504     pidtid = get_current_pidtid()
 505     if message and len(message) > 0:
 506         LOGGING_SUFFIXES_BY_PIDTID[pidtid] = message
 507     elif pidtid in LOGGING_PREFIXES_BY_PIDTID:
 508         del LOGGING_SUFFIXES_BY_PIDTID[pidtid]
 509
 510
 511 class MillisecondAwareOptionallyPrependingFormatter(logging.Formatter):
 512     """A formatter for adding milliseconds to log messages which, for
 513     whatever reason, the default Python logger doesn't do.
 514
 515     This formatter also consults a map of pid+tid -> message from this
 516     module allowing threads to optionally and automatically prepend a
 517     message to all logging data they output.  If the pid+tid is not
 518     found nothing is prepended.
 519
 520     .. note::
 521
 522         You probably don't need to use this directly but it is
 523         wired in under :meth:`initialize_logging` so that the
 524         timestamps in log messages have millisecond level
 525         precision.
 526
 527     """
 528
 529     converter = datetime.datetime.fromtimestamp  # type: ignore
 530
 531     @overrides
 532     def format(self, record):
 533         pidtid = get_current_pidtid()
 534         prefix = LOGGING_PREFIXES_BY_PIDTID.get(pidtid, None)
 535         if prefix:
 536             record.msg = prefix + record.msg
 537         suffix = LOGGING_SUFFIXES_BY_PIDTID.get(pidtid, None)
 538         if suffix:
 539             record.msg = record.msg + suffix
 540         return super().format(record)
 541
 542     @overrides
 543     def formatTime(self, record, datefmt=None):
 544         ct = MillisecondAwareOptionallyPrependingFormatter.converter(
 545             record.created, pytz.timezone("US/Pacific")
 546         )
 547         if datefmt:
 548             s = ct.strftime(datefmt)
 549         else:
 550             t = ct.strftime("%Y-%m-%d %H:%M:%S")
 551             s = f"{t},{record.msecs:%03d}"
 552         return s
 553
 554
 555 def _log_about_logging(
 556     logger,
 557     default_logging_level,
 558     preexisting_handlers_count,
 559     fmt,
 560     facility_name,
 561 ):
 562     """This is invoked automatically after logging is initialized such
 563     that the first messages in the log are about how logging itself
 564     was configured.
 565     """
 566     level_name = logging._levelToName.get(
 567         default_logging_level, str(default_logging_level)
 568     )
 569     logger.debug("Initialized global logging; logging level is %s.", level_name)
 570     if (
 571         config.config["logging_clear_preexisting_handlers"]
 572         and preexisting_handlers_count > 0
 573     ):
 574         logger.debug(
 575             "Logging cleared %d global handlers (--logging_clear_preexisting_handlers)",
 576             preexisting_handlers_count,
 577         )
 578     logger.debug('Logging format specification is "%s"', fmt)
 579     if config.config["logging_debug_threads"]:
 580         logger.debug(
 581             "...Logging format spec captures tid/pid. (--logging_debug_threads)"
 582         )
 583     if config.config["logging_debug_modules"]:
 584         logger.debug(
 585             "...Logging format spec captures files/functions/lineno. (--logging_debug_modules)"
 586         )
 587     if config.config["logging_syslog"]:
 588         logger.debug(
 589             "Logging to syslog as %s with priority mapping based on level. (--logging_syslog)",
 590             facility_name,
 591         )
 592     if config.config["logging_filename"]:
 593         logger.debug(
 594             'Logging to file "%s". (--logging_filename)',
 595             config.config["logging_filename"],
 596         )
 597         logger.debug(
 598             "...with %d bytes max file size. (--logging_filename_maxsize)",
 599             config.config["logging_filename_maxsize"],
 600         )
 601         logger.debug(
 602             "...and %d rotating backup file count. (--logging_filename_count)",
 603             config.config["logging_filename_count"],
 604         )
 605     if config.config["logging_console"]:
 606         logger.debug("Logging to the console (stderr). (--logging_console)")
 607     if config.config["logging_info_is_print"]:
 608         logger.debug(
 609             "Logging logger.info messages will be repeated on stdout. (--logging_info_is_print)"
 610         )
 611     if config.config["logging_squelch_repeats"]:
 612         logger.debug(
 613             "Logging code allowed to request repeated messages be squelched. (--logging_squelch_repeats)"
 614         )
 615     else:
 616         logger.debug(
 617             "Logging code forbidden to request messages be squelched; all messages logged. (--no_logging_squelch_repeats)"
 618         )
 619     if config.config["logging_probabilistically"]:
 620         logger.debug(
 621             "Logging code is allowed to request probabilistic logging. (--logging_probabilistically)"
 622         )
 623     else:
 624         logger.debug(
 625             "Logging code is forbidden to request probabilistic logging; messages always logged. (--no_logging_probabilistically)"
 626         )
 627     if config.config["lmodule"]:
 628         logger.debug(
 629             f'Logging dynamic per-module logging enabled. (--lmodule={config.config["lmodule"]})'
 630         )
 631     if config.config["logging_captures_prints"]:
 632         logger.debug(
 633             "Logging will capture printed data as logger.info messages. (--logging_captures_prints)"
 634         )
 635
 636
 637 def initialize_logging(logger=None) -> logging.Logger:
 638     """Initialize logging for the program.  See module level comments
 639     for information about what functionality this provides and how to
 640     enable or disable functionality via the commandline.
 641
 642     If you use the
 643     :meth:`bootstrap.initialize` decorator on your program's entry point,
 644     it will call this for you.  See :meth:`pyutils.bootstrap.initialize`
 645     for more details.
 646     """
 647     global LOGGING_INITIALIZED
 648     if LOGGING_INITIALIZED:
 649         return logging.getLogger()
 650     LOGGING_INITIALIZED = True
 651
 652     if logger is None:
 653         logger = logging.getLogger()
 654
 655     # --logging_clear_preexisting_handlers removes logging handlers
 656     # that were registered by global statements during imported module
 657     # setup.
 658     preexisting_handlers_count = 0
 659     assert config.has_been_parsed()
 660     if config.config["logging_clear_preexisting_handlers"]:
 661         while logger.hasHandlers():
 662             logger.removeHandler(logger.handlers[0])
 663             preexisting_handlers_count += 1
 664
 665     # --logging_config_file pulls logging settings from a config file
 666     # skipping the rest of this setup.
 667     if config.config["logging_config_file"] is not None:
 668         fileConfig(config.config["logging_config_file"])
 669         return logger
 670
 671     handlers: List[logging.Handler] = []
 672     handler: Optional[logging.Handler] = None
 673
 674     # Global default logging level (--logging_level); messages below
 675     # this level will be silenced.
 676     logging_level = config.config["logging_level"]
 677     assert logging_level
 678     logging_level = logging_level.upper()
 679     default_logging_level = getattr(logging, logging_level, None)
 680     if not isinstance(default_logging_level, int):
 681         raise ValueError(f'Invalid level: {config.config["logging_level"]}')
 682
 683     # Custom or default --logging_format?
 684     if config.config["logging_format"]:
 685         fmt = config.config["logging_format"]
 686     elif config.config["logging_syslog"]:
 687         fmt = "%(levelname).1s:%(filename)s[%(process)d]: %(message)s"
 688     else:
 689         fmt = "%(levelname).1s:%(asctime)s: %(message)s"
 690
 691     # --logging_debug_threads and --logging_debug_modules both affect
 692     # the format by prepending information about the pid/tid or
 693     # file/function.
 694     if config.config["logging_debug_threads"]:
 695         fmt = f"%(process)d.%(thread)d|{fmt}"
 696     if config.config["logging_debug_modules"]:
 697         fmt = f"%(filename)s:%(funcName)s:%(lineno)s|{fmt}"
 698
 699     # --logging_syslog (optionally with --logging_syslog_facility)
 700     # sets up for logging to use the standard system syslogd as a
 701     # sink.
 702     facility_name = None
 703     if config.config["logging_syslog"]:
 704         if sys.platform not in ("win32", "cygwin"):
 705             if config.config["logging_syslog_facility"]:
 706                 facility_name = "LOG_" + config.config["logging_syslog_facility"]
 707             facility = SysLogHandler.__dict__.get(facility_name, SysLogHandler.LOG_USER)  # type: ignore
 708             assert facility is not None
 709             handler = SysLogHandler(facility=facility, address="/dev/log")
 710             handler.setFormatter(
 711                 MillisecondAwareOptionallyPrependingFormatter(
 712                     fmt=fmt,
 713                     datefmt=config.config["logging_date_format"],
 714                 )
 715             )
 716             handlers.append(handler)
 717
 718     # --logging_filename (with friends --logging_filename_count and
 719     # --logging_filename_maxsize) set up logging to a file on the
 720     # filesystem with automatic rotation when it gets too big.
 721     if config.config["logging_filename"]:
 722         max_bytes = config.config["logging_filename_maxsize"]
 723         assert max_bytes and isinstance(max_bytes, int)
 724         backup_count = config.config["logging_filename_count"]
 725         assert backup_count and isinstance(backup_count, int)
 726         handler = RotatingFileHandler(
 727             config.config["logging_filename"],
 728             maxBytes=max_bytes,
 729             backupCount=backup_count,
 730         )
 731         handler.setFormatter(
 732             MillisecondAwareOptionallyPrependingFormatter(
 733                 fmt=fmt,
 734                 datefmt=config.config["logging_date_format"],
 735             )
 736         )
 737         handlers.append(handler)
 738
 739     # --logging_console is, ahem, logging to the console.
 740     if config.config["logging_console"]:
 741         handler = logging.StreamHandler(sys.stderr)
 742         handler.setFormatter(
 743             MillisecondAwareOptionallyPrependingFormatter(
 744                 fmt=fmt,
 745                 datefmt=config.config["logging_date_format"],
 746             )
 747         )
 748         handlers.append(handler)
 749
 750     if len(handlers) == 0:
 751         handlers.append(logging.NullHandler())
 752     for handler in handlers:
 753         logger.addHandler(handler)
 754
 755     # --logging_info_is_print echoes any message to logger.info(x) as
 756     # a print statement on stdout.
 757     if config.config["logging_info_is_print"]:
 758         handler = logging.StreamHandler(sys.stdout)
 759         handler.addFilter(OnlyInfoFilter())
 760         logger.addHandler(handler)
 761
 762     # --logging_squelch_repeats allows code to request repeat logging
 763     # messages (identical log site and message contents) to be
 764     # silenced.  Logging code must request this explicitly, it isn't
 765     # automatic.  This option just allows the silencing to happen.
 766     if config.config["logging_squelch_repeats"]:
 767         for handler in handlers:
 768             handler.addFilter(SquelchRepeatedMessagesFilter())
 769
 770     # --logging_probabilistically allows code to request
 771     # non-deterministic logging where messages have some probability
 772     # of being produced.  Logging code must request this explicitly.
 773     # This option just allows the non-deterministic behavior to
 774     # happen.  Disabling it will cause every log message to be
 775     # produced.
 776     if config.config["logging_probabilistically"]:
 777         for handler in handlers:
 778             handler.addFilter(ProbabilisticFilter())
 779
 780     # --lmodule is a way to have a special logging level for just on
 781     # module or one set of modules that is different than the one set
 782     # globally via --logging_level.
 783     for handler in handlers:
 784         handler.addFilter(
 785             DynamicPerScopeLoggingLevelFilter(
 786                 default_logging_level,
 787                 config.config["lmodule"],
 788             )
 789         )
 790     logger.setLevel(0)
 791     logger.propagate = False
 792
 793     # --logging_captures_prints, if set, will capture and log.info
 794     # anything printed on stdout.
 795     if config.config["logging_captures_prints"]:
 796         import builtins
 797
 798         def print_and_also_log(*arg, **kwarg):
 799             f = kwarg.get("file", None)
 800             if f == sys.stderr:
 801                 logger.warning(*arg)
 802             else:
 803                 logger.info(*arg)
 804             BUILT_IN_PRINT(*arg, **kwarg)
 805
 806         builtins.print = print_and_also_log
 807
 808     # At this point the logger is ready, handlers are set up,
 809     # etc... so log about the logging configuration.
 810     _log_about_logging(
 811         logger,
 812         default_logging_level,
 813         preexisting_handlers_count,
 814         fmt,
 815         facility_name,
 816     )
 817     return logger
 818
 819
 820 def get_logger(name: str = ""):
 821     """Get the global logger"""
 822     logger = logging.getLogger(name)
 823     return initialize_logging(logger)
 824
 825
 826 def tprint(*args, **kwargs) -> None:
 827     """Legacy function for printing a message augmented with thread id
 828     still needed by some code.  Please use --logging_debug_threads in
 829     new code.
 830     """
 831     if config.config["logging_debug_threads"]:
 832         from pyutils.parallelize.thread_utils import current_thread_id
 833
 834         print(f"{current_thread_id()}", end="")
 835         print(*args, **kwargs)
 836     else:
 837         pass
 838
 839
 840 class OutputMultiplexer(object):
 841     """A class that broadcasts printed messages to several sinks
 842     (including various logging levels, different files, different file
 843     handles, the house log, etc...).  See also
 844     :class:`OutputMultiplexerContext` for an easy usage pattern.
 845     """
 846
 847     class Destination(enum.IntEnum):
 848         """Bits in the destination_bitv bitvector.  Used to indicate the
 849         output destination."""
 850
 851         # fmt: off
 852         LOG_DEBUG = 0x01     #  ⎫
 853         LOG_INFO = 0x02      #  ⎪
 854         LOG_WARNING = 0x04   #  ⎬ Must provide logger to the c'tor.
 855         LOG_ERROR = 0x08     #  ⎪
 856         LOG_CRITICAL = 0x10  #  ⎭
 857         FILENAMES = 0x20     # Must provide a filename to the c'tor.
 858         FILEHANDLES = 0x40   # Must provide a handle to the c'tor.
 859         HLOG = 0x80
 860         ALL_LOG_DESTINATIONS = (
 861             LOG_DEBUG | LOG_INFO | LOG_WARNING | LOG_ERROR | LOG_CRITICAL
 862         )
 863         ALL_OUTPUT_DESTINATIONS = 0x8F
 864         # fmt: on
 865
 866     def __init__(
 867         self,
 868         destination_bitv: int,
 869         *,
 870         logger=None,
 871         filenames: Optional[Iterable[str]] = None,
 872         handles: Optional[Iterable[io.TextIOWrapper]] = None,
 873     ):
 874         """
 875         Constructs the OutputMultiplexer instance.
 876
 877         Args:
 878             destination_bitv: a bitvector where each bit represents an
 879                 output destination.  Multiple bits may be set.
 880             logger: if LOG_* bits are set, you must pass a logger here.
 881             filenames: if FILENAMES bit is set, this should be a list of
 882                 files you'd like to output into.  This code handles opening
 883                 and closing said files.
 884             handles: if FILEHANDLES bit is set, this should be a list of
 885                 already opened filehandles you'd like to output into.  The
 886                 handles will remain open after the scope of the multiplexer.
 887         """
 888         if logger is None:
 889             logger = logging.getLogger(None)
 890         self.logger = logger
 891
 892         self.f: Optional[List[Any]] = None
 893         if filenames is not None:
 894             self.f = [open(filename, "wb", buffering=0) for filename in filenames]
 895         else:
 896             if destination_bitv & OutputMultiplexer.Destination.FILENAMES:
 897                 raise ValueError("Filenames argument is required if bitv & FILENAMES")
 898             self.f = None
 899
 900         self.h: Optional[List[Any]] = None
 901         if handles is not None:
 902             self.h = list(handles)
 903         else:
 904             if destination_bitv & OutputMultiplexer.Destination.FILEHANDLES:
 905                 raise ValueError("Handle argument is required if bitv & FILEHANDLES")
 906             self.h = None
 907
 908         self.set_destination_bitv(destination_bitv)
 909
 910     def get_destination_bitv(self):
 911         """Where are we outputting?"""
 912         return self.destination_bitv
 913
 914     def set_destination_bitv(self, destination_bitv: int):
 915         """Change the output destination_bitv to the one provided."""
 916         if destination_bitv & self.Destination.FILENAMES and self.f is None:
 917             raise ValueError("Filename argument is required if bitv & FILENAMES")
 918         if destination_bitv & self.Destination.FILEHANDLES and self.h is None:
 919             raise ValueError("Handle argument is required if bitv & FILEHANDLES")
 920         self.destination_bitv = destination_bitv
 921
 922     def print(self, *args, **kwargs):
 923         """Produce some output to all sinks."""
 924         from pyutils.string_utils import _sprintf, strip_escape_sequences
 925
 926         end = kwargs.pop("end", None)
 927         if end is not None:
 928             if not isinstance(end, str):
 929                 raise TypeError("end must be None or a string")
 930         sep = kwargs.pop("sep", None)
 931         if sep is not None:
 932             if not isinstance(sep, str):
 933                 raise TypeError("sep must be None or a string")
 934         if kwargs:
 935             raise TypeError("invalid keyword arguments to print()")
 936         buf = _sprintf(*args, end="", sep=sep)
 937         if sep is None:
 938             sep = " "
 939         if end is None:
 940             end = "\n"
 941         if end == "\n":
 942             buf += "\n"
 943         if self.destination_bitv & self.Destination.FILENAMES and self.f is not None:
 944             for _ in self.f:
 945                 _.write(buf.encode("utf-8"))
 946                 _.flush()
 947
 948         if self.destination_bitv & self.Destination.FILEHANDLES and self.h is not None:
 949             for _ in self.h:
 950                 _.write(buf)
 951                 _.flush()
 952
 953         buf = strip_escape_sequences(buf)
 954         if self.logger is not None:
 955             if self.destination_bitv & self.Destination.LOG_DEBUG:
 956                 self.logger.debug(buf)
 957             if self.destination_bitv & self.Destination.LOG_INFO:
 958                 self.logger.info(buf)
 959             if self.destination_bitv & self.Destination.LOG_WARNING:
 960                 self.logger.warning(buf)
 961             if self.destination_bitv & self.Destination.LOG_ERROR:
 962                 self.logger.error(buf)
 963             if self.destination_bitv & self.Destination.LOG_CRITICAL:
 964                 self.logger.critical(buf)
 965         if self.destination_bitv & self.Destination.HLOG:
 966             hlog(buf)
 967
 968     def close(self):
 969         """Close all open files."""
 970         if self.f is not None:
 971             for _ in self.f:
 972                 _.close()
 973
 974
 975 class OutputMultiplexerContext(OutputMultiplexer, contextlib.ContextDecorator):
 976     """
 977     A context that uses an :class:`OutputMultiplexer`.  e.g.::
 978
 979         with OutputMultiplexerContext(
 980                 OutputMultiplexer.LOG_INFO |
 981                 OutputMultiplexer.LOG_DEBUG |
 982                 OutputMultiplexer.FILENAMES |
 983                 OutputMultiplexer.FILEHANDLES,
 984                 filenames = [ '/tmp/foo.log', '/var/log/bar.log' ],
 985                 handles = [ f, g ]
 986             ) as mplex:
 987                 mplex.print("This is a log message!")
 988     """
 989
 990     def __init__(
 991         self,
 992         destination_bitv: OutputMultiplexer.Destination,
 993         *,
 994         logger=None,
 995         filenames=None,
 996         handles=None,
 997     ):
 998         """
 999         Args:
1000             destination_bitv: a bitvector that indicates where we should
1001                 send output.  See :class:`OutputMultiplexer` for options.
1002             logger: optional logger to use for log destination messages.
1003             filenames: optional filenames to write for filename destination
1004                 messages.
1005             handles: optional open filehandles to write for filehandle
1006                 destination messages.
1007         """
1008         super().__init__(
1009             destination_bitv,
1010             logger=logger,
1011             filenames=filenames,
1012             handles=handles,
1013         )
1014
1015     def __enter__(self):
1016         return self
1017
1018     def __exit__(self, etype, value, traceback) -> bool:
1019         super().close()
1020         if etype is not None:
1021             return False
1022         return True
1023
1024
1025 def hlog(message: str) -> None:
1026     """Write a message to the house log (syslog facility local7 priority
1027     info) by calling `/usr/bin/logger`.  This is pretty hacky but used
1028     by a bunch of (my) code.  Another way to do this would be to use
1029     :code:`--logging_syslog` and :code:`--logging_syslog_facility` but
1030     I can't actually say that's easier.
1031
1032     TODO: this needs to move.
1033     """
1034     message = message.replace("'", "'\"'\"'")
1035     os.system(f"/usr/bin/logger -p local7.info -- '{message}'")
1036
1037
1038 if __name__ == "__main__":
1039     import doctest
1040
1041     doctest.testmod()