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