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         super().__init__()
 227         self.counters: collections.Counter = collections.Counter()
 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(['NOTSET', 'DEBUG', 'INFO', 'WARNING', 'ERROR', 'CRITICAL'])
 261         self.default_logging_level = default_logging_level
 262         self.level_by_scope = {}
 263         if per_scope_logging_levels is not None:
 264             for chunk in per_scope_logging_levels.split(','):
 265                 if '=' not in chunk:
 266                     print(
 267                         f'Malformed lmodule directive: "{chunk}", missing "=".  Ignored.',
 268                         file=sys.stderr,
 269                     )
 270                     continue
 271                 try:
 272                     (scope, level) = chunk.split('=')
 273                 except ValueError:
 274                     print(
 275                         f'Malformed lmodule directive: "{chunk}".  Ignored.',
 276                         file=sys.stderr,
 277                     )
 278                     continue
 279                 scope = scope.strip()
 280                 level = level.strip().upper()
 281                 if level not in self.valid_levels:
 282                     print(
 283                         f'Malformed lmodule directive: "{chunk}", bad level.  Ignored.',
 284                         file=sys.stderr,
 285                     )
 286                     continue
 287                 self.level_by_scope[scope] = DynamicPerScopeLoggingLevelFilter.level_name_to_level(
 288                     level
 289                 )
 290
 291     @overrides
 292     def filter(self, record: logging.LogRecord) -> bool:
 293         # First try to find a logging level by scope (--lmodule)
 294         if len(self.level_by_scope) > 0:
 295             min_level = None
 296             for scope in (
 297                 record.module,
 298                 f'{record.module}:{record.funcName}',
 299                 f':{record.funcName}',
 300             ):
 301                 level = self.level_by_scope.get(scope, None)
 302                 if level is not None:
 303                     if min_level is None or level < min_level:
 304                         min_level = level
 305
 306             # If we found one, use it instead of the global default level.
 307             if min_level is not None:
 308                 return record.levelno >= min_level
 309
 310         # Otherwise, use the global logging level (--logging_level)
 311         return record.levelno >= self.default_logging_level
 312
 313
 314 # A map from function_identifier -> probability of logging (0.0%..100.0%)
 315 probabilistic_logging_levels: Dict[str, float] = {}
 316
 317
 318 def logging_is_probabilistic(probability_of_logging: float) -> Callable:
 319     """
 320     A decorator that indicates that all logging statements within the
 321     scope of a particular (marked) function are not deterministic
 322     (i.e. they do not always unconditionally log) but rather are
 323     probabilistic (i.e. they log N% of the time randomly).
 324
 325     Note that this functionality can be disabled (forcing all logged
 326     messages to produce output) via the --no_logging_probabilistically
 327     cmdline argument.
 328
 329     This affects *ALL* logging statements within the marked function.
 330
 331     """
 332
 333     def probabilistic_logging_wrapper(f: Callable):
 334         import function_utils
 335
 336         identifier = function_utils.function_identifier(f)
 337         probabilistic_logging_levels[identifier] = probability_of_logging
 338         return f
 339
 340     return probabilistic_logging_wrapper
 341
 342
 343 class ProbabilisticFilter(logging.Filter):
 344     """
 345     A filter that logs messages probabilistically (i.e. randomly at some
 346     percent chance).
 347
 348     This filter only affects logging messages from functions that have
 349     been tagged with the @logging_utils.probabilistic_logging decorator.
 350
 351     """
 352
 353     @overrides
 354     def filter(self, record: logging.LogRecord) -> bool:
 355         id1 = f'{record.module}:{record.funcName}'
 356         if id1 not in probabilistic_logging_levels:
 357             return True
 358         threshold = probabilistic_logging_levels[id1]
 359         return (random.random() * 100.0) <= threshold
 360
 361
 362 class OnlyInfoFilter(logging.Filter):
 363     """
 364     A filter that only logs messages produced at the INFO logging
 365     level.  This is used by the logging_info_is_print commandline
 366     option to select a subset of the logging stream to send to a
 367     stdout handler.
 368
 369     """
 370
 371     @overrides
 372     def filter(self, record: logging.LogRecord):
 373         return record.levelno == logging.INFO
 374
 375
 376 class MillisecondAwareFormatter(logging.Formatter):
 377     """
 378     A formatter for adding milliseconds to log messages which, for
 379     whatever reason, the default python logger doesn't do.
 380
 381     """
 382
 383     converter = datetime.datetime.fromtimestamp  # type: ignore
 384
 385     @overrides
 386     def formatTime(self, record, datefmt=None):
 387         ct = MillisecondAwareFormatter.converter(record.created, pytz.timezone("US/Pacific"))
 388         if datefmt:
 389             s = ct.strftime(datefmt)
 390         else:
 391             t = ct.strftime("%Y-%m-%d %H:%M:%S")
 392             s = "%s,%03d" % (t, record.msecs)
 393         return s
 394
 395
 396 def log_about_logging(
 397     logger,
 398     default_logging_level,
 399     preexisting_handlers_count,
 400     fmt,
 401     facility_name,
 402 ):
 403     level_name = logging._levelToName.get(default_logging_level, str(default_logging_level))
 404     logger.debug(f'Initialized global logging; default logging level is {level_name}.')
 405     if config.config['logging_clear_preexisting_handlers'] and preexisting_handlers_count > 0:
 406         msg = f'Logging cleared {preexisting_handlers_count} global handlers (--logging_clear_preexisting_handlers)'
 407         logger.warning(msg)
 408     logger.debug(f'Logging format specification is "{fmt}"')
 409     if config.config['logging_debug_threads']:
 410         logger.debug('...Logging format spec captures tid/pid (--logging_debug_threads)')
 411     if config.config['logging_debug_modules']:
 412         logger.debug(
 413             '...Logging format spec captures files/functions/lineno (--logging_debug_modules)'
 414         )
 415     if config.config['logging_syslog']:
 416         logger.debug(f'Logging to syslog as {facility_name} with priority mapping based on level')
 417     if config.config['logging_filename']:
 418         logger.debug(f'Logging to filename {config.config["logging_filename"]}')
 419         logger.debug(f'...with {config.config["logging_filename_maxsize"]} bytes max file size.')
 420         logger.debug(
 421             f'...and {config.config["logging_filename_count"]} rotating backup file count.'
 422         )
 423     if config.config['logging_console']:
 424         logger.debug('Logging to the console (stderr).')
 425     if config.config['logging_info_is_print']:
 426         logger.debug(
 427             'Logging logger.info messages will be repeated on stdout (--logging_info_is_print)'
 428         )
 429     if config.config['logging_squelch_repeats']:
 430         logger.debug(
 431             'Logging code allowed to request repeated messages be squelched (--logging_squelch_repeats)'
 432         )
 433     else:
 434         logger.debug(
 435             'Logging code forbidden to request messages be squelched; all messages logged (--no_logging_squelch_repeats)'
 436         )
 437     if config.config['logging_probabilistically']:
 438         logger.debug(
 439             'Logging code is allowed to request probabilistic logging (--logging_probabilistically)'
 440         )
 441     else:
 442         logger.debug(
 443             'Logging code is forbidden to request probabilistic logging; messages always logged (--no_logging_probabilistically)'
 444         )
 445     if config.config['lmodule']:
 446         logger.debug(
 447             f'Logging dynamic per-module logging enabled (--lmodule={config.config["lmodule"]})'
 448         )
 449     if config.config['logging_captures_prints']:
 450         logger.debug(
 451             'Logging will capture printed data as logger.info messages (--logging_captures_prints)'
 452         )
 453
 454
 455 def initialize_logging(logger=None) -> logging.Logger:
 456     global logging_initialized
 457     if logging_initialized:
 458         return logging.getLogger()
 459     logging_initialized = True
 460
 461     if logger is None:
 462         logger = logging.getLogger()
 463
 464     preexisting_handlers_count = 0
 465     assert config.has_been_parsed()
 466     if config.config['logging_clear_preexisting_handlers']:
 467         while logger.hasHandlers():
 468             logger.removeHandler(logger.handlers[0])
 469             preexisting_handlers_count += 1
 470
 471     if config.config['logging_config_file'] is not None:
 472         fileConfig(config.config['logging_config_file'])
 473         return logger
 474
 475     handlers: List[logging.Handler] = []
 476     handler: Optional[logging.Handler] = None
 477
 478     # Global default logging level (--logging_level)
 479     default_logging_level = getattr(logging, config.config['logging_level'].upper(), None)
 480     if not isinstance(default_logging_level, int):
 481         raise ValueError('Invalid level: %s' % config.config['logging_level'])
 482
 483     if config.config['logging_format']:
 484         fmt = config.config['logging_format']
 485     else:
 486         if config.config['logging_syslog']:
 487             fmt = '%(levelname).1s:%(filename)s[%(process)d]: %(message)s'
 488         else:
 489             fmt = '%(levelname).1s:%(asctime)s: %(message)s'
 490     if config.config['logging_debug_threads']:
 491         fmt = f'%(process)d.%(thread)d|{fmt}'
 492     if config.config['logging_debug_modules']:
 493         fmt = f'%(filename)s:%(funcName)s:%(lineno)s|{fmt}'
 494
 495     facility_name = None
 496     if config.config['logging_syslog']:
 497         if sys.platform not in ('win32', 'cygwin'):
 498             if config.config['logging_syslog_facility']:
 499                 facility_name = 'LOG_' + config.config['logging_syslog_facility']
 500             facility = SysLogHandler.__dict__.get(facility_name, SysLogHandler.LOG_USER)  # type: ignore
 501             assert facility is not None
 502             handler = SysLogHandler(facility=facility, address='/dev/log')
 503             handler.setFormatter(
 504                 MillisecondAwareFormatter(
 505                     fmt=fmt,
 506                     datefmt=config.config['logging_date_format'],
 507                 )
 508             )
 509             handlers.append(handler)
 510
 511     if config.config['logging_filename']:
 512         handler = RotatingFileHandler(
 513             config.config['logging_filename'],
 514             maxBytes=config.config['logging_filename_maxsize'],
 515             backupCount=config.config['logging_filename_count'],
 516         )
 517         handler.setFormatter(
 518             MillisecondAwareFormatter(
 519                 fmt=fmt,
 520                 datefmt=config.config['logging_date_format'],
 521             )
 522         )
 523         handlers.append(handler)
 524
 525     if config.config['logging_console']:
 526         handler = logging.StreamHandler(sys.stderr)
 527         handler.setFormatter(
 528             MillisecondAwareFormatter(
 529                 fmt=fmt,
 530                 datefmt=config.config['logging_date_format'],
 531             )
 532         )
 533         handlers.append(handler)
 534
 535     if len(handlers) == 0:
 536         handlers.append(logging.NullHandler())
 537
 538     for handler in handlers:
 539         logger.addHandler(handler)
 540
 541     if config.config['logging_info_is_print']:
 542         handler = logging.StreamHandler(sys.stdout)
 543         handler.addFilter(OnlyInfoFilter())
 544         logger.addHandler(handler)
 545
 546     if config.config['logging_squelch_repeats']:
 547         for handler in handlers:
 548             handler.addFilter(SquelchRepeatedMessagesFilter())
 549
 550     if config.config['logging_probabilistically']:
 551         for handler in handlers:
 552             handler.addFilter(ProbabilisticFilter())
 553
 554     for handler in handlers:
 555         handler.addFilter(
 556             DynamicPerScopeLoggingLevelFilter(
 557                 default_logging_level,
 558                 config.config['lmodule'],
 559             )
 560         )
 561     logger.setLevel(0)
 562     logger.propagate = False
 563
 564     if config.config['logging_captures_prints']:
 565         global built_in_print
 566         import builtins
 567
 568         def print_and_also_log(*arg, **kwarg):
 569             f = kwarg.get('file', None)
 570             if f == sys.stderr:
 571                 logger.warning(*arg)
 572             else:
 573                 logger.info(*arg)
 574             built_in_print(*arg, **kwarg)
 575
 576         builtins.print = print_and_also_log
 577
 578     # At this point the logger is ready, handlers are set up,
 579     # etc... so log about the logging configuration.
 580     log_about_logging(
 581         logger,
 582         default_logging_level,
 583         preexisting_handlers_count,
 584         fmt,
 585         facility_name,
 586     )
 587     return logger
 588
 589
 590 def get_logger(name: str = ""):
 591     logger = logging.getLogger(name)
 592     return initialize_logging(logger)
 593
 594
 595 def tprint(*args, **kwargs) -> None:
 596     """Legacy function for printing a message augmented with thread id
 597     still needed by some code.  Please use --logging_debug_threads in
 598     new code.
 599
 600     """
 601     if config.config['logging_debug_threads']:
 602         from thread_utils import current_thread_id
 603
 604         print(f'{current_thread_id()}', end="")
 605         print(*args, **kwargs)
 606     else:
 607         pass
 608
 609
 610 def dprint(*args, **kwargs) -> None:
 611     """Legacy function used to print to stderr still needed by some code.
 612     Please just use normal logging with --logging_console which
 613     accomplishes the same thing in new code.
 614
 615     """
 616     print(*args, file=sys.stderr, **kwargs)
 617
 618
 619 class OutputMultiplexer(object):
 620     """
 621     A class that broadcasts printed messages to several sinks (including
 622     various logging levels, different files, different file handles,
 623     the house log, etc...).  See also OutputMultiplexerContext for an
 624     easy usage pattern.
 625
 626     """
 627
 628     class Destination(enum.IntEnum):
 629         """Bits in the destination_bitv bitvector.  Used to indicate the
 630         output destination."""
 631
 632         # fmt: off
 633         LOG_DEBUG = 0x01     #  ⎫
 634         LOG_INFO = 0x02      #  ⎪
 635         LOG_WARNING = 0x04   #  ⎬ Must provide logger to the c'tor.
 636         LOG_ERROR = 0x08     #  ⎪
 637         LOG_CRITICAL = 0x10  #  ⎭
 638         FILENAMES = 0x20     # Must provide a filename to the c'tor.
 639         FILEHANDLES = 0x40   # Must provide a handle to the c'tor.
 640         HLOG = 0x80
 641         ALL_LOG_DESTINATIONS = (
 642             LOG_DEBUG | LOG_INFO | LOG_WARNING | LOG_ERROR | LOG_CRITICAL
 643         )
 644         ALL_OUTPUT_DESTINATIONS = 0x8F
 645         # fmt: on
 646
 647     def __init__(
 648         self,
 649         destination_bitv: int,
 650         *,
 651         logger=None,
 652         filenames: Optional[Iterable[str]] = None,
 653         handles: Optional[Iterable[io.TextIOWrapper]] = None,
 654     ):
 655         if logger is None:
 656             logger = logging.getLogger(None)
 657         self.logger = logger
 658
 659         self.f: Optional[List[Any]] = None
 660         if filenames is not None:
 661             self.f = [open(filename, 'wb', buffering=0) for filename in filenames]
 662         else:
 663             if destination_bitv & OutputMultiplexer.Destination.FILENAMES:
 664                 raise ValueError("Filenames argument is required if bitv & FILENAMES")
 665             self.f = None
 666
 667         self.h: Optional[List[Any]] = None
 668         if handles is not None:
 669             self.h = [handle for handle in handles]
 670         else:
 671             if destination_bitv & OutputMultiplexer.Destination.FILEHANDLES:
 672                 raise ValueError("Handle argument is required if bitv & FILEHANDLES")
 673             self.h = None
 674
 675         self.set_destination_bitv(destination_bitv)
 676
 677     def get_destination_bitv(self):
 678         return self.destination_bitv
 679
 680     def set_destination_bitv(self, destination_bitv: int):
 681         if destination_bitv & self.Destination.FILENAMES and self.f is None:
 682             raise ValueError("Filename argument is required if bitv & FILENAMES")
 683         if destination_bitv & self.Destination.FILEHANDLES and self.h is None:
 684             raise ValueError("Handle argument is required if bitv & FILEHANDLES")
 685         self.destination_bitv = destination_bitv
 686
 687     def print(self, *args, **kwargs):
 688         from string_utils import sprintf, strip_escape_sequences
 689
 690         end = kwargs.pop("end", None)
 691         if end is not None:
 692             if not isinstance(end, str):
 693                 raise TypeError("end must be None or a string")
 694         sep = kwargs.pop("sep", None)
 695         if sep is not None:
 696             if not isinstance(sep, str):
 697                 raise TypeError("sep must be None or a string")
 698         if kwargs:
 699             raise TypeError("invalid keyword arguments to print()")
 700         buf = sprintf(*args, end="", sep=sep)
 701         if sep is None:
 702             sep = " "
 703         if end is None:
 704             end = "\n"
 705         if end == '\n':
 706             buf += '\n'
 707         if self.destination_bitv & self.Destination.FILENAMES and self.f is not None:
 708             for _ in self.f:
 709                 _.write(buf.encode('utf-8'))
 710                 _.flush()
 711
 712         if self.destination_bitv & self.Destination.FILEHANDLES and self.h is not None:
 713             for _ in self.h:
 714                 _.write(buf)
 715                 _.flush()
 716
 717         buf = strip_escape_sequences(buf)
 718         if self.logger is not None:
 719             if self.destination_bitv & self.Destination.LOG_DEBUG:
 720                 self.logger.debug(buf)
 721             if self.destination_bitv & self.Destination.LOG_INFO:
 722                 self.logger.info(buf)
 723             if self.destination_bitv & self.Destination.LOG_WARNING:
 724                 self.logger.warning(buf)
 725             if self.destination_bitv & self.Destination.LOG_ERROR:
 726                 self.logger.error(buf)
 727             if self.destination_bitv & self.Destination.LOG_CRITICAL:
 728                 self.logger.critical(buf)
 729         if self.destination_bitv & self.Destination.HLOG:
 730             hlog(buf)
 731
 732     def close(self):
 733         if self.f is not None:
 734             for _ in self.f:
 735                 _.close()
 736
 737
 738 class OutputMultiplexerContext(OutputMultiplexer, contextlib.ContextDecorator):
 739     """
 740     A context that uses an OutputMultiplexer.  e.g.
 741
 742         with OutputMultiplexerContext(
 743                 OutputMultiplexer.LOG_INFO |
 744                 OutputMultiplexer.LOG_DEBUG |
 745                 OutputMultiplexer.FILENAMES |
 746                 OutputMultiplexer.FILEHANDLES,
 747                 filenames = [ '/tmp/foo.log', '/var/log/bar.log' ],
 748                 handles = [ f, g ]
 749             ) as mplex:
 750                 mplex.print("This is a log message!")
 751
 752     """
 753
 754     def __init__(
 755         self,
 756         destination_bitv: OutputMultiplexer.Destination,
 757         *,
 758         logger=None,
 759         filenames=None,
 760         handles=None,
 761     ):
 762         super().__init__(
 763             destination_bitv,
 764             logger=logger,
 765             filenames=filenames,
 766             handles=handles,
 767         )
 768
 769     def __enter__(self):
 770         return self
 771
 772     def __exit__(self, etype, value, traceback) -> bool:
 773         super().close()
 774         if etype is not None:
 775             return False
 776         return True
 777
 778
 779 def hlog(message: str) -> None:
 780     """Write a message to the house log (syslog facility local7 priority
 781     info) by calling /usr/bin/logger.  This is pretty hacky but used
 782     by a bunch of code.  Another way to do this would be to use
 783     --logging_syslog and --logging_syslog_facility but I can't
 784     actually say that's easier.
 785
 786     """
 787     message = message.replace("'", "'\"'\"'")
 788     os.system(f"/usr/bin/logger -p local7.info -- '{message}'")
 789
 790
 791 if __name__ == '__main__':
 792     import doctest
 793
 794     doctest.testmod()