logging_utils.py

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