logging_utils.py

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