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