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, 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 = f"{t},{record.msecs:%03d}"
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(f'Invalid level: {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']:
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 = list(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__':