3 """Utilities related to logging."""
14 from logging.config import fileConfig
15 from logging.handlers import RotatingFileHandler, SysLogHandler
16 from typing import Any, Callable, Dict, Iterable, List, Mapping, Optional
19 from overrides import overrides
21 # This module is commonly used by others in here and should avoid
22 # taking any unnecessary dependencies back on them.
26 cfg = config.add_commandline_args(f'Logging ({__file__})', 'Args related to logging')
28 '--logging_config_file',
29 type=argparse_utils.valid_filename,
32 help='Config file containing the logging setup, see: https://docs.python.org/3/howto/logging.html#logging-advanced-tutorial',
38 choices=['NOTSET', 'DEBUG', 'INFO', 'WARNING', 'ERROR', 'CRITICAL'],
40 help='The global default level below which to squelch log messages; see also --lmodule',
46 help='The format for lines logged via the logger module. See: https://docs.python.org/3/library/logging.html#formatter-objects',
49 '--logging_date_format',
51 default='%Y/%m/%dT%H:%M:%S.%f%z',
53 help='The format of any dates in --logging_format.',
57 action=argparse_utils.ActionNoYes,
59 help='Should we log to the console (stderr)',
66 help='The filename of the logfile to write.',
69 '--logging_filename_maxsize',
71 default=(1024 * 1024),
73 help='The maximum size (in bytes) to write to the logging_filename.',
76 '--logging_filename_count',
80 help='The number of logging_filename copies to keep before deleting.',
84 action=argparse_utils.ActionNoYes,
86 help='Should we log to localhost\'s syslog.',
89 '--logging_syslog_facility',
115 metavar='SYSLOG_FACILITY_LIST',
116 help='The default syslog message facility identifier',
119 '--logging_debug_threads',
120 action=argparse_utils.ActionNoYes,
122 help='Should we prepend pid/tid data to all log messages?',
125 '--logging_debug_modules',
126 action=argparse_utils.ActionNoYes,
128 help='Should we prepend module/function data to all log messages?',
131 '--logging_info_is_print',
132 action=argparse_utils.ActionNoYes,
134 help='logging.info also prints to stdout.',
137 '--logging_squelch_repeats',
138 action=argparse_utils.ActionNoYes,
140 help='Do we allow code to indicate that it wants to squelch repeated logging messages or should we always log?',
143 '--logging_probabilistically',
144 action=argparse_utils.ActionNoYes,
146 help='Do we allow probabilistic logging (for code that wants it) or should we always log?',
148 # See also: OutputMultiplexer
150 '--logging_captures_prints',
151 action=argparse_utils.ActionNoYes,
153 help='When calling print, also log.info automatically.',
158 metavar='<SCOPE>=<LEVEL>[,<SCOPE>=<LEVEL>...]',
160 'Allows per-scope logging levels which override the global level set with --logging-level.'
161 + 'Pass a space separated list of <scope>=<level> where <scope> is one of: module, '
162 + 'module:function, or :function and <level> is a logging level (e.g. INFO, DEBUG...)'
166 '--logging_clear_preexisting_handlers',
167 action=argparse_utils.ActionNoYes,
170 'Should logging code clear preexisting global logging handlers and thus insist that is '
171 + 'alone can add handlers. Use this to work around annoying modules that insert global '
172 + 'handlers with formats and logging levels you might now want. Caveat emptor, this may '
173 + 'cause you to miss logging messages.'
177 built_in_print = print
178 logging_initialized = False
181 # A map from logging_callsite_id -> count of logged messages.
182 squelched_logging_counts: Dict[str, int] = {}
185 def squelch_repeated_log_messages(squelch_after_n_repeats: int) -> Callable:
187 A decorator that marks a function as interested in having the logging
188 messages that it produces be squelched (ignored) after it logs the
189 same message more than N times.
191 Note: this decorator affects *ALL* logging messages produced
192 within the decorated function. That said, messages must be
193 identical in order to be squelched. For example, if the same line
194 of code produces different messages (because of, e.g., a format
195 string), the messages are considered to be different.
199 def squelch_logging_wrapper(f: Callable):
200 import function_utils
202 identifier = function_utils.function_identifier(f)
203 squelched_logging_counts[identifier] = squelch_after_n_repeats
206 return squelch_logging_wrapper
209 class SquelchRepeatedMessagesFilter(logging.Filter):
211 A filter that only logs messages from a given site with the same
212 (exact) message at the same logging level N times and ignores
213 subsequent attempts to log.
215 This filter only affects logging messages that repeat more than
216 a threshold number of times from functions that are tagged with
217 the @logging_utils.squelched_logging_ok decorator; others are
220 This functionality is enabled by default but can be disabled via
221 the --no_logging_squelch_repeats commandline flag.
225 def __init__(self) -> None:
227 self.counters: collections.Counter = collections.Counter()
230 def filter(self, record: logging.LogRecord) -> bool:
231 id1 = f'{record.module}:{record.funcName}'
232 if id1 not in squelched_logging_counts:
234 threshold = squelched_logging_counts[id1]
235 logsite = f'{record.pathname}+{record.lineno}+{record.levelno}+{record.msg}'
236 count = self.counters[logsite]
237 self.counters[logsite] += 1
238 return count < threshold
241 class DynamicPerScopeLoggingLevelFilter(logging.Filter):
242 """This filter only allows logging messages from an allow list of
243 module names or module:function names. Blocks others.
248 def level_name_to_level(name: str) -> int:
249 numeric_level = getattr(logging, name, None)
250 if not isinstance(numeric_level, int):
251 raise ValueError(f'Invalid level: {name}')
256 default_logging_level: int,
257 per_scope_logging_levels: str,
260 self.valid_levels = set(['NOTSET', 'DEBUG', 'INFO', 'WARNING', 'ERROR', 'CRITICAL'])
261 self.default_logging_level = default_logging_level
262 self.level_by_scope = {}
263 if per_scope_logging_levels is not None:
264 for chunk in per_scope_logging_levels.split(','):
267 f'Malformed lmodule directive: "{chunk}", missing "=". Ignored.',
272 (scope, level) = chunk.split('=')
275 f'Malformed lmodule directive: "{chunk}". Ignored.',
279 scope = scope.strip()
280 level = level.strip().upper()
281 if level not in self.valid_levels:
283 f'Malformed lmodule directive: "{chunk}", bad level. Ignored.',
287 self.level_by_scope[scope] = DynamicPerScopeLoggingLevelFilter.level_name_to_level(
292 def filter(self, record: logging.LogRecord) -> bool:
293 # First try to find a logging level by scope (--lmodule)
294 if len(self.level_by_scope) > 0:
298 f'{record.module}:{record.funcName}',
299 f':{record.funcName}',
301 level = self.level_by_scope.get(scope, None)
302 if level is not None:
303 if min_level is None or level < min_level:
306 # If we found one, use it instead of the global default level.
307 if min_level is not None:
308 return record.levelno >= min_level
310 # Otherwise, use the global logging level (--logging_level)
311 return record.levelno >= self.default_logging_level
314 # A map from function_identifier -> probability of logging (0.0%..100.0%)
315 probabilistic_logging_levels: Dict[str, float] = {}
318 def logging_is_probabilistic(probability_of_logging: float) -> Callable:
320 A decorator that indicates that all logging statements within the
321 scope of a particular (marked) function are not deterministic
322 (i.e. they do not always unconditionally log) but rather are
323 probabilistic (i.e. they log N% of the time randomly).
325 Note that this functionality can be disabled (forcing all logged
326 messages to produce output) via the --no_logging_probabilistically
329 This affects *ALL* logging statements within the marked function.
333 def probabilistic_logging_wrapper(f: Callable):
334 import function_utils
336 identifier = function_utils.function_identifier(f)
337 probabilistic_logging_levels[identifier] = probability_of_logging
340 return probabilistic_logging_wrapper
343 class ProbabilisticFilter(logging.Filter):
345 A filter that logs messages probabilistically (i.e. randomly at some
348 This filter only affects logging messages from functions that have
349 been tagged with the @logging_utils.probabilistic_logging decorator.
354 def filter(self, record: logging.LogRecord) -> bool:
355 id1 = f'{record.module}:{record.funcName}'
356 if id1 not in probabilistic_logging_levels:
358 threshold = probabilistic_logging_levels[id1]
359 return (random.random() * 100.0) <= threshold
362 class OnlyInfoFilter(logging.Filter):
364 A filter that only logs messages produced at the INFO logging
365 level. This is used by the logging_info_is_print commandline
366 option to select a subset of the logging stream to send to a
372 def filter(self, record: logging.LogRecord):
373 return record.levelno == logging.INFO
376 class MillisecondAwareFormatter(logging.Formatter):
378 A formatter for adding milliseconds to log messages which, for
379 whatever reason, the default python logger doesn't do.
383 converter = datetime.datetime.fromtimestamp # type: ignore
386 def formatTime(self, record, datefmt=None):
387 ct = MillisecondAwareFormatter.converter(record.created, pytz.timezone("US/Pacific"))
389 s = ct.strftime(datefmt)
391 t = ct.strftime("%Y-%m-%d %H:%M:%S")
392 s = "%s,%03d" % (t, record.msecs)
396 def log_about_logging(
398 default_logging_level,
399 preexisting_handlers_count,
403 level_name = logging._levelToName.get(default_logging_level, str(default_logging_level))
404 logger.debug(f'Initialized global logging; default logging level is {level_name}.')
405 if config.config['logging_clear_preexisting_handlers'] and preexisting_handlers_count > 0:
406 msg = f'Logging cleared {preexisting_handlers_count} global handlers (--logging_clear_preexisting_handlers)'
408 logger.debug(f'Logging format specification is "{fmt}"')
409 if config.config['logging_debug_threads']:
410 logger.debug('...Logging format spec captures tid/pid (--logging_debug_threads)')
411 if config.config['logging_debug_modules']:
413 '...Logging format spec captures files/functions/lineno (--logging_debug_modules)'
415 if config.config['logging_syslog']:
416 logger.debug(f'Logging to syslog as {facility_name} with priority mapping based on level')
417 if config.config['logging_filename']:
418 logger.debug(f'Logging to filename {config.config["logging_filename"]}')
419 logger.debug(f'...with {config.config["logging_filename_maxsize"]} bytes max file size.')
421 f'...and {config.config["logging_filename_count"]} rotating backup file count.'
423 if config.config['logging_console']:
424 logger.debug('Logging to the console (stderr).')
425 if config.config['logging_info_is_print']:
427 'Logging logger.info messages will be repeated on stdout (--logging_info_is_print)'
429 if config.config['logging_squelch_repeats']:
431 'Logging code allowed to request repeated messages be squelched (--logging_squelch_repeats)'
435 'Logging code forbidden to request messages be squelched; all messages logged (--no_logging_squelch_repeats)'
437 if config.config['logging_probabilistically']:
439 'Logging code is allowed to request probabilistic logging (--logging_probabilistically)'
443 'Logging code is forbidden to request probabilistic logging; messages always logged (--no_logging_probabilistically)'
445 if config.config['lmodule']:
447 f'Logging dynamic per-module logging enabled (--lmodule={config.config["lmodule"]})'
449 if config.config['logging_captures_prints']:
451 'Logging will capture printed data as logger.info messages (--logging_captures_prints)'
455 def initialize_logging(logger=None) -> logging.Logger:
456 global logging_initialized
457 if logging_initialized:
458 return logging.getLogger()
459 logging_initialized = True
462 logger = logging.getLogger()
464 preexisting_handlers_count = 0
465 assert config.has_been_parsed()
466 if config.config['logging_clear_preexisting_handlers']:
467 while logger.hasHandlers():
468 logger.removeHandler(logger.handlers[0])
469 preexisting_handlers_count += 1
471 if config.config['logging_config_file'] is not None:
472 fileConfig(config.config['logging_config_file'])
475 handlers: List[logging.Handler] = []
476 handler: Optional[logging.Handler] = None
478 # Global default logging level (--logging_level)
479 default_logging_level = getattr(logging, config.config['logging_level'].upper(), None)
480 if not isinstance(default_logging_level, int):
481 raise ValueError('Invalid level: %s' % config.config['logging_level'])
483 if config.config['logging_format']:
484 fmt = config.config['logging_format']
486 if config.config['logging_syslog']:
487 fmt = '%(levelname).1s:%(filename)s[%(process)d]: %(message)s'
489 fmt = '%(levelname).1s:%(asctime)s: %(message)s'
490 if config.config['logging_debug_threads']:
491 fmt = f'%(process)d.%(thread)d|{fmt}'
492 if config.config['logging_debug_modules']:
493 fmt = f'%(filename)s:%(funcName)s:%(lineno)s|{fmt}'
496 if config.config['logging_syslog']:
497 if sys.platform not in ('win32', 'cygwin'):
498 if config.config['logging_syslog_facility']:
499 facility_name = 'LOG_' + config.config['logging_syslog_facility']
500 facility = SysLogHandler.__dict__.get(facility_name, SysLogHandler.LOG_USER) # type: ignore
501 assert facility is not None
502 handler = SysLogHandler(facility=facility, address='/dev/log')
503 handler.setFormatter(
504 MillisecondAwareFormatter(
506 datefmt=config.config['logging_date_format'],
509 handlers.append(handler)
511 if config.config['logging_filename']:
512 handler = RotatingFileHandler(
513 config.config['logging_filename'],
514 maxBytes=config.config['logging_filename_maxsize'],
515 backupCount=config.config['logging_filename_count'],
517 handler.setFormatter(
518 MillisecondAwareFormatter(
520 datefmt=config.config['logging_date_format'],
523 handlers.append(handler)
525 if config.config['logging_console']:
526 handler = logging.StreamHandler(sys.stderr)
527 handler.setFormatter(
528 MillisecondAwareFormatter(
530 datefmt=config.config['logging_date_format'],
533 handlers.append(handler)
535 if len(handlers) == 0:
536 handlers.append(logging.NullHandler())
538 for handler in handlers:
539 logger.addHandler(handler)
541 if config.config['logging_info_is_print']:
542 handler = logging.StreamHandler(sys.stdout)
543 handler.addFilter(OnlyInfoFilter())
544 logger.addHandler(handler)
546 if config.config['logging_squelch_repeats']:
547 for handler in handlers:
548 handler.addFilter(SquelchRepeatedMessagesFilter())
550 if config.config['logging_probabilistically']:
551 for handler in handlers:
552 handler.addFilter(ProbabilisticFilter())
554 for handler in handlers:
556 DynamicPerScopeLoggingLevelFilter(
557 default_logging_level,
558 config.config['lmodule'],
562 logger.propagate = False
564 if config.config['logging_captures_prints']:
565 global built_in_print
568 def print_and_also_log(*arg, **kwarg):
569 f = kwarg.get('file', None)
574 built_in_print(*arg, **kwarg)
576 builtins.print = print_and_also_log
578 # At this point the logger is ready, handlers are set up,
579 # etc... so log about the logging configuration.
582 default_logging_level,
583 preexisting_handlers_count,
590 def get_logger(name: str = ""):
591 logger = logging.getLogger(name)
592 return initialize_logging(logger)
595 def tprint(*args, **kwargs) -> None:
596 """Legacy function for printing a message augmented with thread id
597 still needed by some code. Please use --logging_debug_threads in
601 if config.config['logging_debug_threads']:
602 from thread_utils import current_thread_id
604 print(f'{current_thread_id()}', end="")
605 print(*args, **kwargs)
610 def dprint(*args, **kwargs) -> None:
611 """Legacy function used to print to stderr still needed by some code.
612 Please just use normal logging with --logging_console which
613 accomplishes the same thing in new code.
616 print(*args, file=sys.stderr, **kwargs)
619 class OutputMultiplexer(object):
621 A class that broadcasts printed messages to several sinks (including
622 various logging levels, different files, different file handles,
623 the house log, etc...). See also OutputMultiplexerContext for an
628 class Destination(enum.IntEnum):
629 """Bits in the destination_bitv bitvector. Used to indicate the
630 output destination."""
635 LOG_WARNING = 0x04 # ⎬ Must provide logger to the c'tor.
637 LOG_CRITICAL = 0x10 # ⎭
638 FILENAMES = 0x20 # Must provide a filename to the c'tor.
639 FILEHANDLES = 0x40 # Must provide a handle to the c'tor.
641 ALL_LOG_DESTINATIONS = (
642 LOG_DEBUG | LOG_INFO | LOG_WARNING | LOG_ERROR | LOG_CRITICAL
644 ALL_OUTPUT_DESTINATIONS = 0x8F
649 destination_bitv: int,
652 filenames: Optional[Iterable[str]] = None,
653 handles: Optional[Iterable[io.TextIOWrapper]] = None,
656 logger = logging.getLogger(None)
659 self.f: Optional[List[Any]] = None
660 if filenames is not None:
661 self.f = [open(filename, 'wb', buffering=0) for filename in filenames]
663 if destination_bitv & OutputMultiplexer.Destination.FILENAMES:
664 raise ValueError("Filenames argument is required if bitv & FILENAMES")
667 self.h: Optional[List[Any]] = None
668 if handles is not None:
669 self.h = [handle for handle in handles]
671 if destination_bitv & OutputMultiplexer.Destination.FILEHANDLES:
672 raise ValueError("Handle argument is required if bitv & FILEHANDLES")
675 self.set_destination_bitv(destination_bitv)
677 def get_destination_bitv(self):
678 return self.destination_bitv
680 def set_destination_bitv(self, destination_bitv: int):
681 if destination_bitv & self.Destination.FILENAMES and self.f is None:
682 raise ValueError("Filename argument is required if bitv & FILENAMES")
683 if destination_bitv & self.Destination.FILEHANDLES and self.h is None:
684 raise ValueError("Handle argument is required if bitv & FILEHANDLES")
685 self.destination_bitv = destination_bitv
687 def print(self, *args, **kwargs):
688 from string_utils import sprintf, strip_escape_sequences
690 end = kwargs.pop("end", None)
692 if not isinstance(end, str):
693 raise TypeError("end must be None or a string")
694 sep = kwargs.pop("sep", None)
696 if not isinstance(sep, str):
697 raise TypeError("sep must be None or a string")
699 raise TypeError("invalid keyword arguments to print()")
700 buf = sprintf(*args, end="", sep=sep)
707 if self.destination_bitv & self.Destination.FILENAMES and self.f is not None:
709 _.write(buf.encode('utf-8'))
712 if self.destination_bitv & self.Destination.FILEHANDLES and self.h is not None:
717 buf = strip_escape_sequences(buf)
718 if self.logger is not None:
719 if self.destination_bitv & self.Destination.LOG_DEBUG:
720 self.logger.debug(buf)
721 if self.destination_bitv & self.Destination.LOG_INFO:
722 self.logger.info(buf)
723 if self.destination_bitv & self.Destination.LOG_WARNING:
724 self.logger.warning(buf)
725 if self.destination_bitv & self.Destination.LOG_ERROR:
726 self.logger.error(buf)
727 if self.destination_bitv & self.Destination.LOG_CRITICAL:
728 self.logger.critical(buf)
729 if self.destination_bitv & self.Destination.HLOG:
733 if self.f is not None:
738 class OutputMultiplexerContext(OutputMultiplexer, contextlib.ContextDecorator):
740 A context that uses an OutputMultiplexer. e.g.
742 with OutputMultiplexerContext(
743 OutputMultiplexer.LOG_INFO |
744 OutputMultiplexer.LOG_DEBUG |
745 OutputMultiplexer.FILENAMES |
746 OutputMultiplexer.FILEHANDLES,
747 filenames = [ '/tmp/foo.log', '/var/log/bar.log' ],
750 mplex.print("This is a log message!")
756 destination_bitv: OutputMultiplexer.Destination,
772 def __exit__(self, etype, value, traceback) -> bool:
774 if etype is not None:
779 def hlog(message: str) -> None:
780 """Write a message to the house log (syslog facility local7 priority
781 info) by calling /usr/bin/logger. This is pretty hacky but used
782 by a bunch of code. Another way to do this would be to use
783 --logging_syslog and --logging_syslog_facility but I can't
784 actually say that's easier.
787 message = message.replace("'", "'\"'\"'")
788 os.system(f"/usr/bin/logger -p local7.info -- '{message}'")
791 if __name__ == '__main__':