logging_utils.py

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