2 # -*- coding: utf-8 -*-
4 """Utilities related to logging."""
15 from logging.config import fileConfig
16 from logging.handlers import RotatingFileHandler, SysLogHandler
17 from typing import Any, Callable, Dict, Iterable, List, Mapping, Optional
20 from overrides import overrides
22 # This module is commonly used by others in here and should avoid
23 # taking any unnecessary dependencies back on them.
27 cfg = config.add_commandline_args(f'Logging ({__file__})', 'Args related to logging')
29 '--logging_config_file',
30 type=argparse_utils.valid_filename,
33 help='Config file containing the logging setup, see: https://docs.python.org/3/howto/logging.html#logging-advanced-tutorial',
39 choices=['NOTSET', 'DEBUG', 'INFO', 'WARNING', 'ERROR', 'CRITICAL'],
41 help='The global default level below which to squelch log messages; see also --lmodule',
47 help='The format for lines logged via the logger module. See: https://docs.python.org/3/library/logging.html#formatter-objects',
50 '--logging_date_format',
52 default='%Y/%m/%dT%H:%M:%S.%f%z',
54 help='The format of any dates in --logging_format.',
58 action=argparse_utils.ActionNoYes,
60 help='Should we log to the console (stderr)',
67 help='The filename of the logfile to write.',
70 '--logging_filename_maxsize',
72 default=(1024 * 1024),
74 help='The maximum size (in bytes) to write to the logging_filename.',
77 '--logging_filename_count',
81 help='The number of logging_filename copies to keep before deleting.',
85 action=argparse_utils.ActionNoYes,
87 help='Should we log to localhost\'s syslog.',
90 '--logging_syslog_facility',
116 metavar='SYSLOG_FACILITY_LIST',
117 help='The default syslog message facility identifier',
120 '--logging_debug_threads',
121 action=argparse_utils.ActionNoYes,
123 help='Should we prepend pid/tid data to all log messages?',
126 '--logging_debug_modules',
127 action=argparse_utils.ActionNoYes,
129 help='Should we prepend module/function data to all log messages?',
132 '--logging_info_is_print',
133 action=argparse_utils.ActionNoYes,
135 help='logging.info also prints to stdout.',
138 '--logging_squelch_repeats',
139 action=argparse_utils.ActionNoYes,
141 help='Do we allow code to indicate that it wants to squelch repeated logging messages or should we always log?',
144 '--logging_probabilistically',
145 action=argparse_utils.ActionNoYes,
147 help='Do we allow probabilistic logging (for code that wants it) or should we always log?',
149 # See also: OutputMultiplexer
151 '--logging_captures_prints',
152 action=argparse_utils.ActionNoYes,
154 help='When calling print, also log.info automatically.',
159 metavar='<SCOPE>=<LEVEL>[,<SCOPE>=<LEVEL>...]',
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...)'
167 '--logging_clear_preexisting_handlers',
168 action=argparse_utils.ActionNoYes,
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.'
178 built_in_print = print
179 logging_initialized = False
182 # A map from logging_callsite_id -> count of logged messages.
183 squelched_logging_counts: Dict[str, int] = {}
186 def squelch_repeated_log_messages(squelch_after_n_repeats: int) -> Callable:
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.
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.
200 def squelch_logging_wrapper(f: Callable):
201 import function_utils
203 identifier = function_utils.function_identifier(f)
204 squelched_logging_counts[identifier] = squelch_after_n_repeats
207 return squelch_logging_wrapper
210 class SquelchRepeatedMessagesFilter(logging.Filter):
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.
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
221 This functionality is enabled by default but can be disabled via
222 the --no_logging_squelch_repeats commandline flag.
226 def __init__(self) -> None:
228 self.counters: collections.Counter = collections.Counter()
231 def filter(self, record: logging.LogRecord) -> bool:
232 id1 = f'{record.module}:{record.funcName}'
233 if id1 not in squelched_logging_counts:
235 threshold = squelched_logging_counts[id1]
236 logsite = f'{record.pathname}+{record.lineno}+{record.levelno}+{record.msg}'
237 count = self.counters[logsite]
238 self.counters[logsite] += 1
239 return count < threshold
242 class DynamicPerScopeLoggingLevelFilter(logging.Filter):
243 """This filter only allows logging messages from an allow list of
244 module names or module:function names. Blocks others.
249 def level_name_to_level(name: str) -> int:
250 numeric_level = getattr(logging, name, None)
251 if not isinstance(numeric_level, int):
252 raise ValueError(f'Invalid level: {name}')
257 default_logging_level: int,
258 per_scope_logging_levels: str,
261 self.valid_levels = set(['NOTSET', 'DEBUG', 'INFO', 'WARNING', 'ERROR', 'CRITICAL'])
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(','):
268 f'Malformed lmodule directive: "{chunk}", missing "=". Ignored.',
273 (scope, level) = chunk.split('=')
276 f'Malformed lmodule directive: "{chunk}". Ignored.',
280 scope = scope.strip()
281 level = level.strip().upper()
282 if level not in self.valid_levels:
284 f'Malformed lmodule directive: "{chunk}", bad level. Ignored.',
288 self.level_by_scope[scope] = DynamicPerScopeLoggingLevelFilter.level_name_to_level(
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:
299 f'{record.module}:{record.funcName}',
300 f':{record.funcName}',
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:
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
311 # Otherwise, use the global logging level (--logging_level)
312 return record.levelno >= self.default_logging_level
315 # A map from function_identifier -> probability of logging (0.0%..100.0%)
316 probabilistic_logging_levels: Dict[str, float] = {}
319 def logging_is_probabilistic(probability_of_logging: float) -> Callable:
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).
326 Note that this functionality can be disabled (forcing all logged
327 messages to produce output) via the --no_logging_probabilistically
330 This affects *ALL* logging statements within the marked function.
334 def probabilistic_logging_wrapper(f: Callable):
335 import function_utils
337 identifier = function_utils.function_identifier(f)
338 probabilistic_logging_levels[identifier] = probability_of_logging
341 return probabilistic_logging_wrapper
344 class ProbabilisticFilter(logging.Filter):
346 A filter that logs messages probabilistically (i.e. randomly at some
349 This filter only affects logging messages from functions that have
350 been tagged with the @logging_utils.probabilistic_logging decorator.
355 def filter(self, record: logging.LogRecord) -> bool:
356 id1 = f'{record.module}:{record.funcName}'
357 if id1 not in probabilistic_logging_levels:
359 threshold = probabilistic_logging_levels[id1]
360 return (random.random() * 100.0) <= threshold
363 class OnlyInfoFilter(logging.Filter):
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
373 def filter(self, record: logging.LogRecord):
374 return record.levelno == logging.INFO
377 class MillisecondAwareFormatter(logging.Formatter):
379 A formatter for adding milliseconds to log messages which, for
380 whatever reason, the default python logger doesn't do.
384 converter = datetime.datetime.fromtimestamp # type: ignore
387 def formatTime(self, record, datefmt=None):
388 ct = MillisecondAwareFormatter.converter(record.created, pytz.timezone("US/Pacific"))
390 s = ct.strftime(datefmt)
392 t = ct.strftime("%Y-%m-%d %H:%M:%S")
393 s = "%s,%03d" % (t, record.msecs)
397 def log_about_logging(
399 default_logging_level,
400 preexisting_handlers_count,
404 level_name = logging._levelToName.get(default_logging_level, str(default_logging_level))
405 logger.debug(f'Initialized global logging; default logging level is {level_name}.')
406 if config.config['logging_clear_preexisting_handlers'] and preexisting_handlers_count > 0:
407 msg = f'Logging cleared {preexisting_handlers_count} global handlers (--logging_clear_preexisting_handlers)'
409 logger.debug(f'Logging format specification is "{fmt}"')
410 if config.config['logging_debug_threads']:
411 logger.debug('...Logging format spec captures tid/pid (--logging_debug_threads)')
412 if config.config['logging_debug_modules']:
414 '...Logging format spec captures files/functions/lineno (--logging_debug_modules)'
416 if config.config['logging_syslog']:
417 logger.debug(f'Logging to syslog as {facility_name} with priority mapping based on level')
418 if config.config['logging_filename']:
419 logger.debug(f'Logging to filename {config.config["logging_filename"]}')
420 logger.debug(f'...with {config.config["logging_filename_maxsize"]} bytes max file size.')
422 f'...and {config.config["logging_filename_count"]} rotating backup file count.'
424 if config.config['logging_console']:
425 logger.debug('Logging to the console (stderr).')
426 if config.config['logging_info_is_print']:
428 'Logging logger.info messages will be repeated on stdout (--logging_info_is_print)'
430 if config.config['logging_squelch_repeats']:
432 'Logging code allowed to request repeated messages be squelched (--logging_squelch_repeats)'
436 'Logging code forbidden to request messages be squelched; all messages logged (--no_logging_squelch_repeats)'
438 if config.config['logging_probabilistically']:
440 'Logging code is allowed to request probabilistic logging (--logging_probabilistically)'
444 'Logging code is forbidden to request probabilistic logging; messages always logged (--no_logging_probabilistically)'
446 if config.config['lmodule']:
448 f'Logging dynamic per-module logging enabled (--lmodule={config.config["lmodule"]})'
450 if config.config['logging_captures_prints']:
452 'Logging will capture printed data as logger.info messages (--logging_captures_prints)'
456 def initialize_logging(logger=None) -> logging.Logger:
457 global logging_initialized
458 if logging_initialized:
459 return logging.getLogger()
460 logging_initialized = True
463 logger = logging.getLogger()
465 preexisting_handlers_count = 0
466 assert config.has_been_parsed()
467 if config.config['logging_clear_preexisting_handlers']:
468 while logger.hasHandlers():
469 logger.removeHandler(logger.handlers[0])
470 preexisting_handlers_count += 1
472 if config.config['logging_config_file'] is not None:
473 fileConfig(config.config['logging_config_file'])
476 handlers: List[logging.Handler] = []
477 handler: Optional[logging.Handler] = None
479 # Global default logging level (--logging_level)
480 default_logging_level = getattr(logging, config.config['logging_level'].upper(), None)
481 if not isinstance(default_logging_level, int):
482 raise ValueError('Invalid level: %s' % config.config['logging_level'])
484 if config.config['logging_format']:
485 fmt = config.config['logging_format']
487 if config.config['logging_syslog']:
488 fmt = '%(levelname).1s:%(filename)s[%(process)d]: %(message)s'
490 fmt = '%(levelname).1s:%(asctime)s: %(message)s'
491 if config.config['logging_debug_threads']:
492 fmt = f'%(process)d.%(thread)d|{fmt}'
493 if config.config['logging_debug_modules']:
494 fmt = f'%(filename)s:%(funcName)s:%(lineno)s|{fmt}'
497 if config.config['logging_syslog']:
498 if sys.platform not in ('win32', 'cygwin'):
499 if config.config['logging_syslog_facility']:
500 facility_name = 'LOG_' + config.config['logging_syslog_facility']
501 facility = SysLogHandler.__dict__.get(facility_name, SysLogHandler.LOG_USER) # type: ignore
502 assert facility is not None
503 handler = SysLogHandler(facility=facility, address='/dev/log')
504 handler.setFormatter(
505 MillisecondAwareFormatter(
507 datefmt=config.config['logging_date_format'],
510 handlers.append(handler)
512 if config.config['logging_filename']:
513 handler = RotatingFileHandler(
514 config.config['logging_filename'],
515 maxBytes=config.config['logging_filename_maxsize'],
516 backupCount=config.config['logging_filename_count'],
518 handler.setFormatter(
519 MillisecondAwareFormatter(
521 datefmt=config.config['logging_date_format'],
524 handlers.append(handler)
526 if config.config['logging_console']:
527 handler = logging.StreamHandler(sys.stderr)
528 handler.setFormatter(
529 MillisecondAwareFormatter(
531 datefmt=config.config['logging_date_format'],
534 handlers.append(handler)
536 if len(handlers) == 0:
537 handlers.append(logging.NullHandler())
539 for handler in handlers:
540 logger.addHandler(handler)
542 if config.config['logging_info_is_print']:
543 handler = logging.StreamHandler(sys.stdout)
544 handler.addFilter(OnlyInfoFilter())
545 logger.addHandler(handler)
547 if config.config['logging_squelch_repeats']:
548 for handler in handlers:
549 handler.addFilter(SquelchRepeatedMessagesFilter())
551 if config.config['logging_probabilistically']:
552 for handler in handlers:
553 handler.addFilter(ProbabilisticFilter())
555 for handler in handlers:
557 DynamicPerScopeLoggingLevelFilter(
558 default_logging_level,
559 config.config['lmodule'],
563 logger.propagate = False
565 if config.config['logging_captures_prints']:
566 global built_in_print
569 def print_and_also_log(*arg, **kwarg):
570 f = kwarg.get('file', None)
575 built_in_print(*arg, **kwarg)
577 builtins.print = print_and_also_log
579 # At this point the logger is ready, handlers are set up,
580 # etc... so log about the logging configuration.
583 default_logging_level,
584 preexisting_handlers_count,
591 def get_logger(name: str = ""):
592 logger = logging.getLogger(name)
593 return initialize_logging(logger)
596 def tprint(*args, **kwargs) -> None:
597 """Legacy function for printing a message augmented with thread id
598 still needed by some code. Please use --logging_debug_threads in
602 if config.config['logging_debug_threads']:
603 from thread_utils import current_thread_id
605 print(f'{current_thread_id()}', end="")
606 print(*args, **kwargs)
611 def dprint(*args, **kwargs) -> None:
612 """Legacy function used to print to stderr still needed by some code.
613 Please just use normal logging with --logging_console which
614 accomplishes the same thing in new code.
617 print(*args, file=sys.stderr, **kwargs)
620 class OutputMultiplexer(object):
622 A class that broadcasts printed messages to several sinks (including
623 various logging levels, different files, different file handles,
624 the house log, etc...). See also OutputMultiplexerContext for an
629 class Destination(enum.IntEnum):
630 """Bits in the destination_bitv bitvector. Used to indicate the
631 output destination."""
636 LOG_WARNING = 0x04 # ⎬ Must provide logger to the c'tor.
638 LOG_CRITICAL = 0x10 # ⎭
639 FILENAMES = 0x20 # Must provide a filename to the c'tor.
640 FILEHANDLES = 0x40 # Must provide a handle to the c'tor.
642 ALL_LOG_DESTINATIONS = (
643 LOG_DEBUG | LOG_INFO | LOG_WARNING | LOG_ERROR | LOG_CRITICAL
645 ALL_OUTPUT_DESTINATIONS = 0x8F
650 destination_bitv: int,
653 filenames: Optional[Iterable[str]] = None,
654 handles: Optional[Iterable[io.TextIOWrapper]] = None,
657 logger = logging.getLogger(None)
660 self.f: Optional[List[Any]] = None
661 if filenames is not None:
662 self.f = [open(filename, 'wb', buffering=0) for filename in filenames]
664 if destination_bitv & OutputMultiplexer.Destination.FILENAMES:
665 raise ValueError("Filenames argument is required if bitv & FILENAMES")
668 self.h: Optional[List[Any]] = None
669 if handles is not None:
670 self.h = [handle for handle in handles]
672 if destination_bitv & OutputMultiplexer.Destination.FILEHANDLES:
673 raise ValueError("Handle argument is required if bitv & FILEHANDLES")
676 self.set_destination_bitv(destination_bitv)
678 def get_destination_bitv(self):
679 return self.destination_bitv
681 def set_destination_bitv(self, destination_bitv: int):
682 if destination_bitv & self.Destination.FILENAMES and self.f is None:
683 raise ValueError("Filename argument is required if bitv & FILENAMES")
684 if destination_bitv & self.Destination.FILEHANDLES and self.h is None:
685 raise ValueError("Handle argument is required if bitv & FILEHANDLES")
686 self.destination_bitv = destination_bitv
688 def print(self, *args, **kwargs):
689 from string_utils import sprintf, strip_escape_sequences
691 end = kwargs.pop("end", None)
693 if not isinstance(end, str):
694 raise TypeError("end must be None or a string")
695 sep = kwargs.pop("sep", None)
697 if not isinstance(sep, str):
698 raise TypeError("sep must be None or a string")
700 raise TypeError("invalid keyword arguments to print()")
701 buf = sprintf(*args, end="", sep=sep)
708 if self.destination_bitv & self.Destination.FILENAMES and self.f is not None:
710 _.write(buf.encode('utf-8'))
713 if self.destination_bitv & self.Destination.FILEHANDLES and self.h is not None:
718 buf = strip_escape_sequences(buf)
719 if self.logger is not None:
720 if self.destination_bitv & self.Destination.LOG_DEBUG:
721 self.logger.debug(buf)
722 if self.destination_bitv & self.Destination.LOG_INFO:
723 self.logger.info(buf)
724 if self.destination_bitv & self.Destination.LOG_WARNING:
725 self.logger.warning(buf)
726 if self.destination_bitv & self.Destination.LOG_ERROR:
727 self.logger.error(buf)
728 if self.destination_bitv & self.Destination.LOG_CRITICAL:
729 self.logger.critical(buf)
730 if self.destination_bitv & self.Destination.HLOG:
734 if self.f is not None:
739 class OutputMultiplexerContext(OutputMultiplexer, contextlib.ContextDecorator):
741 A context that uses an OutputMultiplexer. e.g.
743 with OutputMultiplexerContext(
744 OutputMultiplexer.LOG_INFO |
745 OutputMultiplexer.LOG_DEBUG |
746 OutputMultiplexer.FILENAMES |
747 OutputMultiplexer.FILEHANDLES,
748 filenames = [ '/tmp/foo.log', '/var/log/bar.log' ],
751 mplex.print("This is a log message!")
757 destination_bitv: OutputMultiplexer.Destination,
773 def __exit__(self, etype, value, traceback) -> bool:
775 if etype is not None:
780 def hlog(message: str) -> None:
781 """Write a message to the house log (syslog facility local7 priority
782 info) by calling /usr/bin/logger. This is pretty hacky but used
783 by a bunch of code. Another way to do this would be to use
784 --logging_syslog and --logging_syslog_facility but I can't
785 actually say that's easier.
788 message = message.replace("'", "'\"'\"'")
789 os.system(f"/usr/bin/logger -p local7.info -- '{message}'")
792 if __name__ == '__main__':