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