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:
226 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(
261 ['NOTSET', 'DEBUG', 'INFO', 'WARNING', 'ERROR', 'CRITICAL']
263 self.default_logging_level = default_logging_level
264 self.level_by_scope = {}
265 if per_scope_logging_levels is not None:
266 for chunk in per_scope_logging_levels.split(','):
269 f'Malformed lmodule directive: "{chunk}", missing "=". Ignored.',
274 (scope, level) = chunk.split('=')
277 f'Malformed lmodule directive: "{chunk}". Ignored.',
281 scope = scope.strip()
282 level = level.strip().upper()
283 if level not in self.valid_levels:
285 f'Malformed lmodule directive: "{chunk}", bad level. Ignored.',
291 ] = DynamicPerScopeLoggingLevelFilter.level_name_to_level(level)
294 def filter(self, record: logging.LogRecord) -> bool:
295 # First try to find a logging level by scope (--lmodule)
296 if len(self.level_by_scope) > 0:
300 f'{record.module}:{record.funcName}',
301 f':{record.funcName}',
303 level = self.level_by_scope.get(scope, None)
304 if level is not None:
305 if min_level is None or level < min_level:
308 # If we found one, use it instead of the global default level.
309 if min_level is not None:
310 return record.levelno >= min_level
312 # Otherwise, use the global logging level (--logging_level)
313 return record.levelno >= self.default_logging_level
316 # A map from function_identifier -> probability of logging (0.0%..100.0%)
317 probabilistic_logging_levels: Dict[str, float] = {}
320 def logging_is_probabilistic(probability_of_logging: float) -> Callable:
322 A decorator that indicates that all logging statements within the
323 scope of a particular (marked) function are not deterministic
324 (i.e. they do not always unconditionally log) but rather are
325 probabilistic (i.e. they log N% of the time randomly).
327 Note that this functionality can be disabled (forcing all logged
328 messages to produce output) via the --no_logging_probabilistically
331 This affects *ALL* logging statements within the marked function.
335 def probabilistic_logging_wrapper(f: Callable):
336 import function_utils
338 identifier = function_utils.function_identifier(f)
339 probabilistic_logging_levels[identifier] = probability_of_logging
342 return probabilistic_logging_wrapper
345 class ProbabilisticFilter(logging.Filter):
347 A filter that logs messages probabilistically (i.e. randomly at some
350 This filter only affects logging messages from functions that have
351 been tagged with the @logging_utils.probabilistic_logging decorator.
356 def filter(self, record: logging.LogRecord) -> bool:
357 id1 = f'{record.module}:{record.funcName}'
358 if id1 not in probabilistic_logging_levels:
360 threshold = probabilistic_logging_levels[id1]
361 return (random.random() * 100.0) <= threshold
364 class OnlyInfoFilter(logging.Filter):
366 A filter that only logs messages produced at the INFO logging
367 level. This is used by the logging_info_is_print commandline
368 option to select a subset of the logging stream to send to a
374 def filter(self, record: logging.LogRecord):
375 return record.levelno == logging.INFO
378 class MillisecondAwareFormatter(logging.Formatter):
380 A formatter for adding milliseconds to log messages which, for
381 whatever reason, the default python logger doesn't do.
385 converter = datetime.datetime.fromtimestamp # type: ignore
388 def formatTime(self, record, datefmt=None):
389 ct = MillisecondAwareFormatter.converter(
390 record.created, pytz.timezone("US/Pacific")
393 s = ct.strftime(datefmt)
395 t = ct.strftime("%Y-%m-%d %H:%M:%S")
396 s = "%s,%03d" % (t, record.msecs)
400 def log_about_logging(
401 logger, default_logging_level, preexisting_handlers_count, fmt, facility_name
403 level_name = logging._levelToName.get(
404 default_logging_level, str(default_logging_level)
406 logger.debug(f'Initialized global logging; default logging level is {level_name}.')
408 config.config['logging_clear_preexisting_handlers']
409 and preexisting_handlers_count > 0
411 msg = f'Logging cleared {preexisting_handlers_count} global handlers (--logging_clear_preexisting_handlers)'
413 logger.debug(f'Logging format specification is "{fmt}"')
414 if config.config['logging_debug_threads']:
416 '...Logging format spec captures tid/pid (--logging_debug_threads)'
418 if config.config['logging_debug_modules']:
420 '...Logging format spec captures files/functions/lineno (--logging_debug_modules)'
422 if config.config['logging_syslog']:
424 f'Logging to syslog as {facility_name} with priority mapping based on level'
426 if config.config['logging_filename']:
427 logger.debug(f'Logging to filename {config.config["logging_filename"]}')
429 f'...with {config.config["logging_filename_maxsize"]} bytes max file size.'
432 f'...and {config.config["logging_filename_count"]} rotating backup file count.'
434 if config.config['logging_console']:
435 logger.debug('Logging to the console (stderr).')
436 if config.config['logging_info_is_print']:
438 'Logging logger.info messages will be repeated on stdout (--logging_info_is_print)'
440 if config.config['logging_squelch_repeats']:
442 'Logging code allowed to request repeated messages be squelched (--logging_squelch_repeats)'
446 'Logging code forbidden to request messages be squelched; all messages logged (--no_logging_squelch_repeats)'
448 if config.config['logging_probabilistically']:
450 'Logging code is allowed to request probabilistic logging (--logging_probabilistically)'
454 'Logging code is forbidden to request probabilistic logging; messages always logged (--no_logging_probabilistically)'
456 if config.config['lmodule']:
458 f'Logging dynamic per-module logging enabled (--lmodule={config.config["lmodule"]})'
460 if config.config['logging_captures_prints']:
462 'Logging will capture printed data as logger.info messages (--logging_captures_prints)'
466 def initialize_logging(logger=None) -> logging.Logger:
467 global logging_initialized
468 if logging_initialized:
469 return logging.getLogger()
470 logging_initialized = True
473 logger = logging.getLogger()
475 preexisting_handlers_count = 0
476 assert config.has_been_parsed()
477 if config.config['logging_clear_preexisting_handlers']:
478 while logger.hasHandlers():
479 logger.removeHandler(logger.handlers[0])
480 preexisting_handlers_count += 1
482 if config.config['logging_config_file'] is not None:
483 fileConfig(config.config['logging_config_file'])
486 handlers: List[logging.Handler] = []
487 handler: Optional[logging.Handler] = None
489 # Global default logging level (--logging_level)
490 default_logging_level = getattr(
491 logging, config.config['logging_level'].upper(), None
493 if not isinstance(default_logging_level, int):
494 raise ValueError('Invalid level: %s' % config.config['logging_level'])
496 if config.config['logging_format']:
497 fmt = config.config['logging_format']
499 if config.config['logging_syslog']:
500 fmt = '%(levelname).1s:%(filename)s[%(process)d]: %(message)s'
502 fmt = '%(levelname).1s:%(asctime)s: %(message)s'
503 if config.config['logging_debug_threads']:
504 fmt = f'%(process)d.%(thread)d|{fmt}'
505 if config.config['logging_debug_modules']:
506 fmt = f'%(filename)s:%(funcName)s:%(lineno)s|{fmt}'
509 if config.config['logging_syslog']:
510 if sys.platform not in ('win32', 'cygwin'):
511 if config.config['logging_syslog_facility']:
512 facility_name = 'LOG_' + config.config['logging_syslog_facility']
513 facility = SysLogHandler.__dict__.get(facility_name, SysLogHandler.LOG_USER) # type: ignore
515 handler = SysLogHandler(facility=facility, address='/dev/log')
516 handler.setFormatter(
517 MillisecondAwareFormatter(
519 datefmt=config.config['logging_date_format'],
522 handlers.append(handler)
524 if config.config['logging_filename']:
525 handler = RotatingFileHandler(
526 config.config['logging_filename'],
527 maxBytes=config.config['logging_filename_maxsize'],
528 backupCount=config.config['logging_filename_count'],
530 handler.setFormatter(
531 MillisecondAwareFormatter(
533 datefmt=config.config['logging_date_format'],
536 handlers.append(handler)
538 if config.config['logging_console']:
539 handler = logging.StreamHandler(sys.stderr)
540 handler.setFormatter(
541 MillisecondAwareFormatter(
543 datefmt=config.config['logging_date_format'],
546 handlers.append(handler)
548 if len(handlers) == 0:
549 handlers.append(logging.NullHandler())
551 for handler in handlers:
552 logger.addHandler(handler)
554 if config.config['logging_info_is_print']:
555 handler = logging.StreamHandler(sys.stdout)
556 handler.addFilter(OnlyInfoFilter())
557 logger.addHandler(handler)
559 if config.config['logging_squelch_repeats']:
560 for handler in handlers:
561 handler.addFilter(SquelchRepeatedMessagesFilter())
563 if config.config['logging_probabilistically']:
564 for handler in handlers:
565 handler.addFilter(ProbabilisticFilter())
567 for handler in handlers:
569 DynamicPerScopeLoggingLevelFilter(
570 default_logging_level,
571 config.config['lmodule'],
575 logger.propagate = False
577 if config.config['logging_captures_prints']:
578 global built_in_print
581 def print_and_also_log(*arg, **kwarg):
582 f = kwarg.get('file', None)
587 built_in_print(*arg, **kwarg)
589 builtins.print = print_and_also_log
591 # At this point the logger is ready, handlers are set up,
592 # etc... so log about the logging configuration.
595 default_logging_level,
596 preexisting_handlers_count,
603 def get_logger(name: str = ""):
604 logger = logging.getLogger(name)
605 return initialize_logging(logger)
608 def tprint(*args, **kwargs) -> None:
609 """Legacy function for printing a message augmented with thread id
610 still needed by some code. Please use --logging_debug_threads in
614 if config.config['logging_debug_threads']:
615 from thread_utils import current_thread_id
617 print(f'{current_thread_id()}', end="")
618 print(*args, **kwargs)
623 def dprint(*args, **kwargs) -> None:
624 """Legacy function used to print to stderr still needed by some code.
625 Please just use normal logging with --logging_console which
626 accomplishes the same thing in new code.
629 print(*args, file=sys.stderr, **kwargs)
632 class OutputMultiplexer(object):
634 A class that broadcasts printed messages to several sinks (including
635 various logging levels, different files, different file handles,
636 the house log, etc...). See also OutputMultiplexerContext for an
641 class Destination(enum.IntEnum):
642 """Bits in the destination_bitv bitvector. Used to indicate the
643 output destination."""
648 LOG_WARNING = 0x04 # ⎬ Must provide logger to the c'tor.
650 LOG_CRITICAL = 0x10 # ⎭
651 FILENAMES = 0x20 # Must provide a filename to the c'tor.
652 FILEHANDLES = 0x40 # Must provide a handle to the c'tor.
654 ALL_LOG_DESTINATIONS = (
655 LOG_DEBUG | LOG_INFO | LOG_WARNING | LOG_ERROR | LOG_CRITICAL
657 ALL_OUTPUT_DESTINATIONS = 0x8F
662 destination_bitv: int,
665 filenames: Optional[Iterable[str]] = None,
666 handles: Optional[Iterable[io.TextIOWrapper]] = None,
669 logger = logging.getLogger(None)
672 self.f: Optional[List[Any]] = None
673 if filenames is not None:
674 self.f = [open(filename, 'wb', buffering=0) for filename in filenames]
676 if destination_bitv & OutputMultiplexer.Destination.FILENAMES:
677 raise ValueError("Filenames argument is required if bitv & FILENAMES")
680 self.h: Optional[List[Any]] = None
681 if handles is not None:
682 self.h = [handle for handle in handles]
684 if destination_bitv & OutputMultiplexer.Destination.FILEHANDLES:
685 raise ValueError("Handle argument is required if bitv & FILEHANDLES")
688 self.set_destination_bitv(destination_bitv)
690 def get_destination_bitv(self):
691 return self.destination_bitv
693 def set_destination_bitv(self, destination_bitv: int):
694 if destination_bitv & self.Destination.FILENAMES and self.f is None:
695 raise ValueError("Filename argument is required if bitv & FILENAMES")
696 if destination_bitv & self.Destination.FILEHANDLES and self.h is None:
697 raise ValueError("Handle argument is required if bitv & FILEHANDLES")
698 self.destination_bitv = destination_bitv
700 def print(self, *args, **kwargs):
701 from string_utils import sprintf, strip_escape_sequences
703 end = kwargs.pop("end", None)
705 if not isinstance(end, str):
706 raise TypeError("end must be None or a string")
707 sep = kwargs.pop("sep", None)
709 if not isinstance(sep, str):
710 raise TypeError("sep must be None or a string")
712 raise TypeError("invalid keyword arguments to print()")
713 buf = sprintf(*args, end="", sep=sep)
720 if self.destination_bitv & self.Destination.FILENAMES and self.f is not None:
722 _.write(buf.encode('utf-8'))
725 if self.destination_bitv & self.Destination.FILEHANDLES and self.h is not None:
730 buf = strip_escape_sequences(buf)
731 if self.logger is not None:
732 if self.destination_bitv & self.Destination.LOG_DEBUG:
733 self.logger.debug(buf)
734 if self.destination_bitv & self.Destination.LOG_INFO:
735 self.logger.info(buf)
736 if self.destination_bitv & self.Destination.LOG_WARNING:
737 self.logger.warning(buf)
738 if self.destination_bitv & self.Destination.LOG_ERROR:
739 self.logger.error(buf)
740 if self.destination_bitv & self.Destination.LOG_CRITICAL:
741 self.logger.critical(buf)
742 if self.destination_bitv & self.Destination.HLOG:
746 if self.f is not None:
751 class OutputMultiplexerContext(OutputMultiplexer, contextlib.ContextDecorator):
753 A context that uses an OutputMultiplexer. e.g.
755 with OutputMultiplexerContext(
756 OutputMultiplexer.LOG_INFO |
757 OutputMultiplexer.LOG_DEBUG |
758 OutputMultiplexer.FILENAMES |
759 OutputMultiplexer.FILEHANDLES,
760 filenames = [ '/tmp/foo.log', '/var/log/bar.log' ],
763 mplex.print("This is a log message!")
769 destination_bitv: OutputMultiplexer.Destination,
785 def __exit__(self, etype, value, traceback) -> bool:
787 if etype is not None:
792 def hlog(message: str) -> None:
793 """Write a message to the house log (syslog facility local7 priority
794 info) by calling /usr/bin/logger. This is pretty hacky but used
795 by a bunch of code. Another way to do this would be to use
796 --logging_syslog and --logging_syslog_facility but I can't
797 actually say that's easier.
800 message = message.replace("'", "'\"'\"'")
801 os.system(f"/usr/bin/logger -p local7.info -- '{message}'")
804 if __name__ == '__main__':