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