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