3 """Utilities related to logging."""
11 from logging.handlers import RotatingFileHandler, SysLogHandler
15 from typing import Callable, Iterable, Mapping, Optional
17 from overrides import overrides
20 # This module is commonly used by others in here and should avoid
21 # taking any unnecessary dependencies back on them.
25 cfg = config.add_commandline_args(f'Logging ({__file__})', 'Args related to logging')
27 '--logging_config_file',
28 type=argparse_utils.valid_filename,
31 help='Config file containing the logging setup, see: https://docs.python.org/3/howto/logging.html#logging-advanced-tutorial',
37 choices=['NOTSET', 'DEBUG', 'INFO', 'WARNING', 'ERROR', 'CRITICAL'],
39 help='The global default level below which to squelch log messages; see also --lmodule',
45 help='The format for lines logged via the logger module. See: https://docs.python.org/3/library/logging.html#formatter-objects',
48 '--logging_date_format',
50 default='%Y/%m/%dT%H:%M:%S.%f%z',
52 help='The format of any dates in --logging_format.',
56 action=argparse_utils.ActionNoYes,
58 help='Should we log to the console (stderr)',
65 help='The filename of the logfile to write.',
68 '--logging_filename_maxsize',
70 default=(1024 * 1024),
72 help='The maximum size (in bytes) to write to the logging_filename.',
75 '--logging_filename_count',
79 help='The number of logging_filename copies to keep before deleting.',
83 action=argparse_utils.ActionNoYes,
85 help='Should we log to localhost\'s syslog.',
88 '--logging_syslog_facility',
114 metavar='SYSLOG_FACILITY_LIST',
115 help='The default syslog message facility identifier',
118 '--logging_debug_threads',
119 action=argparse_utils.ActionNoYes,
121 help='Should we prepend pid/tid data to all log messages?',
124 '--logging_debug_modules',
125 action=argparse_utils.ActionNoYes,
127 help='Should we prepend module/function data to all log messages?',
130 '--logging_info_is_print',
131 action=argparse_utils.ActionNoYes,
133 help='logging.info also prints to stdout.',
136 '--logging_squelch_repeats',
137 action=argparse_utils.ActionNoYes,
139 help='Do we allow code to indicate that it wants to squelch repeated logging messages or should we always log?',
142 '--logging_probabilistically',
143 action=argparse_utils.ActionNoYes,
145 help='Do we allow probabilistic logging (for code that wants it) or should we always log?',
147 # See also: OutputMultiplexer
149 '--logging_captures_prints',
150 action=argparse_utils.ActionNoYes,
152 help='When calling print, also log.info automatically.',
157 metavar='<SCOPE>=<LEVEL>[,<SCOPE>=<LEVEL>...]',
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...)'
165 '--logging_clear_preexisting_handlers',
166 action=argparse_utils.ActionNoYes,
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.'
176 built_in_print = print
177 logging_initialized = False
180 # A map from logging_callsite_id -> count of logged messages.
181 squelched_logging_counts: Mapping[str, int] = {}
184 def squelch_repeated_log_messages(squelch_after_n_repeats: int) -> Callable:
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.
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.
198 def squelch_logging_wrapper(f: Callable):
199 import function_utils
201 identifier = function_utils.function_identifier(f)
202 squelched_logging_counts[identifier] = squelch_after_n_repeats
205 return squelch_logging_wrapper
208 class SquelchRepeatedMessagesFilter(logging.Filter):
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.
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
219 This functionality is enabled by default but can be disabled via
220 the --no_logging_squelch_repeats commandline flag.
224 def __init__(self) -> None:
225 self.counters = collections.Counter()
229 def filter(self, record: logging.LogRecord) -> bool:
230 id1 = f'{record.module}:{record.funcName}'
231 if id1 not in squelched_logging_counts:
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
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.
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}')
255 default_logging_level: int,
256 per_scope_logging_levels: str,
259 self.valid_levels = set(
260 ['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.',
290 ] = DynamicPerScopeLoggingLevelFilter.level_name_to_level(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: Mapping[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
387 def formatTime(self, record, datefmt=None):
388 ct = MillisecondAwareFormatter.converter(
389 record.created, pytz.timezone("US/Pacific")
392 s = ct.strftime(datefmt)
394 t = ct.strftime("%Y-%m-%d %H:%M:%S")
395 s = "%s,%03d" % (t, record.msecs)
399 def log_about_logging(
400 logger, default_logging_level, preexisting_handlers_count, fmt, facility_name
402 level_name = logging._levelToName.get(
403 default_logging_level, str(default_logging_level)
405 logger.debug(f'Initialized global logging; default logging level is {level_name}.')
407 config.config['logging_clear_preexisting_handlers']
408 and preexisting_handlers_count > 0
410 msg = f'Logging cleared {preexisting_handlers_count} global handlers (--logging_clear_preexisting_handlers)'
412 logger.debug(f'Logging format specification is "{fmt}"')
413 if config.config['logging_debug_threads']:
415 '...Logging format spec captures tid/pid (--logging_debug_threads)'
417 if config.config['logging_debug_modules']:
419 '...Logging format spec captures files/functions/lineno (--logging_debug_modules)'
421 if config.config['logging_syslog']:
423 f'Logging to syslog as {facility_name} with priority mapping based on level'
425 if config.config['logging_filename']:
426 logger.debug(f'Logging to filename {config.config["logging_filename"]}')
428 f'...with {config.config["logging_filename_maxsize"]} bytes max file size.'
431 f'...and {config.config["logging_filename_count"]} rotating backup file count.'
433 if config.config['logging_console']:
434 logger.debug('Logging to the console (stderr).')
435 if config.config['logging_info_is_print']:
437 'Logging logger.info messages will be repeated on stdout (--logging_info_is_print)'
439 if config.config['logging_squelch_repeats']:
441 'Logging code allowed to request repeated messages be squelched (--logging_squelch_repeats)'
445 'Logging code forbidden to request messages be squelched; all messages logged (--no_logging_squelch_repeats)'
447 if config.config['logging_probabilistically']:
449 'Logging code is allowed to request probabilistic logging (--logging_probabilistically)'
453 'Logging code is forbidden to request probabilistic logging; messages always logged (--no_logging_probabilistically)'
455 if config.config['lmodule']:
457 f'Logging dynamic per-module logging enabled (--lmodule={config.config["lmodule"]})'
459 if config.config['logging_captures_prints']:
461 'Logging will capture printed data as logger.info messages (--logging_captures_prints)'
465 def initialize_logging(logger=None) -> logging.Logger:
466 global logging_initialized
467 if logging_initialized:
469 logging_initialized = True
472 logger = logging.getLogger()
474 preexisting_handlers_count = 0
475 assert config.has_been_parsed()
476 if config.config['logging_clear_preexisting_handlers']:
477 while logger.hasHandlers():
478 logger.removeHandler(logger.handlers[0])
479 preexisting_handlers_count += 1
481 if config.config['logging_config_file'] is not None:
482 logging.config.fileConfig('logging.conf')
487 # Global default logging level (--logging_level)
488 default_logging_level = getattr(
489 logging, config.config['logging_level'].upper(), None
491 if not isinstance(default_logging_level, int):
492 raise ValueError('Invalid level: %s' % config.config['logging_level'])
494 if config.config['logging_format']:
495 fmt = config.config['logging_format']
497 if config.config['logging_syslog']:
498 fmt = '%(levelname).1s:%(filename)s[%(process)d]: %(message)s'
500 fmt = '%(levelname).1s:%(asctime)s: %(message)s'
501 if config.config['logging_debug_threads']:
502 fmt = f'%(process)d.%(thread)d|{fmt}'
503 if config.config['logging_debug_modules']:
504 fmt = f'%(filename)s:%(funcName)s:%(lineno)s|{fmt}'
507 if config.config['logging_syslog']:
508 if sys.platform not in ('win32', 'cygwin'):
509 if config.config['logging_syslog_facility']:
510 facility_name = 'LOG_' + config.config['logging_syslog_facility']
511 facility = SysLogHandler.__dict__.get(facility_name, SysLogHandler.LOG_USER)
512 handler = SysLogHandler(facility=facility, address='/dev/log')
513 handler.setFormatter(
514 MillisecondAwareFormatter(
516 datefmt=config.config['logging_date_format'],
519 handlers.append(handler)
521 if config.config['logging_filename']:
522 handler = RotatingFileHandler(
523 config.config['logging_filename'],
524 maxBytes=config.config['logging_filename_maxsize'],
525 backupCount=config.config['logging_filename_count'],
527 handler.setFormatter(
528 MillisecondAwareFormatter(
530 datefmt=config.config['logging_date_format'],
533 handlers.append(handler)
535 if config.config['logging_console']:
536 handler = logging.StreamHandler(sys.stderr)
537 handler.setFormatter(
538 MillisecondAwareFormatter(
540 datefmt=config.config['logging_date_format'],
543 handlers.append(handler)
545 if len(handlers) == 0:
546 handlers.append(logging.NullHandler())
548 for handler in handlers:
549 logger.addHandler(handler)
551 if config.config['logging_info_is_print']:
552 handler = logging.StreamHandler(sys.stdout)
553 handler.addFilter(OnlyInfoFilter())
554 logger.addHandler(handler)
556 if config.config['logging_squelch_repeats']:
557 for handler in handlers:
558 handler.addFilter(SquelchRepeatedMessagesFilter())
560 if config.config['logging_probabilistically']:
561 for handler in handlers:
562 handler.addFilter(ProbabilisticFilter())
564 for handler in handlers:
566 DynamicPerScopeLoggingLevelFilter(
567 default_logging_level,
568 config.config['lmodule'],
572 logger.propagate = False
574 if config.config['logging_captures_prints']:
575 global built_in_print
578 def print_and_also_log(*arg, **kwarg):
579 f = kwarg.get('file', None)
584 built_in_print(*arg, **kwarg)
586 builtins.print = print_and_also_log
588 # At this point the logger is ready, handlers are set up,
589 # etc... so log about the logging configuration.
592 default_logging_level,
593 preexisting_handlers_count,
600 def get_logger(name: str = ""):
601 logger = logging.getLogger(name)
602 return initialize_logging(logger)
605 def tprint(*args, **kwargs) -> None:
606 """Legacy function for printing a message augmented with thread id
607 still needed by some code. Please use --logging_debug_threads in
611 if config.config['logging_debug_threads']:
612 from thread_utils import current_thread_id
614 print(f'{current_thread_id()}', end="")
615 print(*args, **kwargs)
620 def dprint(*args, **kwargs) -> None:
621 """Legacy function used to print to stderr still needed by some code.
622 Please just use normal logging with --logging_console which
623 accomplishes the same thing in new code.
626 print(*args, file=sys.stderr, **kwargs)
629 class OutputMultiplexer(object):
631 A class that broadcasts printed messages to several sinks (including
632 various logging levels, different files, different file handles,
633 the house log, etc...). See also OutputMultiplexerContext for an
638 class Destination(enum.IntEnum):
639 """Bits in the destination_bitv bitvector. Used to indicate the
640 output destination."""
645 LOG_WARNING = 0x04 # ⎬ Must provide logger to the c'tor.
647 LOG_CRITICAL = 0x10 # ⎭
648 FILENAMES = 0x20 # Must provide a filename to the c'tor.
649 FILEHANDLES = 0x40 # Must provide a handle to the c'tor.
651 ALL_LOG_DESTINATIONS = (
652 LOG_DEBUG | LOG_INFO | LOG_WARNING | LOG_ERROR | LOG_CRITICAL
654 ALL_OUTPUT_DESTINATIONS = 0x8F
659 destination_bitv: int,
662 filenames: Optional[Iterable[str]] = None,
663 handles: Optional[Iterable[io.TextIOWrapper]] = None,
666 logger = logging.getLogger(None)
669 if filenames is not None:
670 self.f = [open(filename, 'wb', buffering=0) for filename in filenames]
672 if destination_bitv & OutputMultiplexer.FILENAMES:
673 raise ValueError("Filenames argument is required if bitv & FILENAMES")
676 if handles is not None:
677 self.h = [handle for handle in handles]
679 if destination_bitv & OutputMultiplexer.Destination.FILEHANDLES:
680 raise ValueError("Handle argument is required if bitv & FILEHANDLES")
683 self.set_destination_bitv(destination_bitv)
685 def get_destination_bitv(self):
686 return self.destination_bitv
688 def set_destination_bitv(self, destination_bitv: int):
689 if destination_bitv & self.Destination.FILENAMES and self.f is None:
690 raise ValueError("Filename argument is required if bitv & FILENAMES")
691 if destination_bitv & self.Destination.FILEHANDLES and self.h is None:
692 raise ValueError("Handle argument is required if bitv & FILEHANDLES")
693 self.destination_bitv = destination_bitv
695 def print(self, *args, **kwargs):
696 from string_utils import sprintf, strip_escape_sequences
698 end = kwargs.pop("end", None)
700 if not isinstance(end, str):
701 raise TypeError("end must be None or a string")
702 sep = kwargs.pop("sep", None)
704 if not isinstance(sep, str):
705 raise TypeError("sep must be None or a string")
707 raise TypeError("invalid keyword arguments to print()")
708 buf = sprintf(*args, end="", sep=sep)
715 if self.destination_bitv & self.Destination.FILENAMES and self.f is not None:
717 _.write(buf.encode('utf-8'))
720 if self.destination_bitv & self.Destination.FILEHANDLES and self.h is not None:
725 buf = strip_escape_sequences(buf)
726 if self.logger is not None:
727 if self.destination_bitv & self.Destination.LOG_DEBUG:
728 self.logger.debug(buf)
729 if self.destination_bitv & self.Destination.LOG_INFO:
730 self.logger.info(buf)
731 if self.destination_bitv & self.Destination.LOG_WARNING:
732 self.logger.warning(buf)
733 if self.destination_bitv & self.Destination.LOG_ERROR:
734 self.logger.error(buf)
735 if self.destination_bitv & self.Destination.LOG_CRITICAL:
736 self.logger.critical(buf)
737 if self.destination_bitv & self.Destination.HLOG:
741 if self.f is not None:
746 class OutputMultiplexerContext(OutputMultiplexer, contextlib.ContextDecorator):
748 A context that uses an OutputMultiplexer. e.g.
750 with OutputMultiplexerContext(
751 OutputMultiplexer.LOG_INFO |
752 OutputMultiplexer.LOG_DEBUG |
753 OutputMultiplexer.FILENAMES |
754 OutputMultiplexer.FILEHANDLES,
755 filenames = [ '/tmp/foo.log', '/var/log/bar.log' ],
758 mplex.print("This is a log message!")
764 destination_bitv: OutputMultiplexer.Destination,
780 def __exit__(self, etype, value, traceback) -> bool:
782 if etype is not None:
787 def hlog(message: str) -> None:
788 """Write a message to the house log (syslog facility local7 priority
789 info) by calling /usr/bin/logger. This is pretty hacky but used
790 by a bunch of code. Another way to do this would be to use
791 --logging_syslog and --logging_syslog_facility but I can't
792 actually say that's easier.
795 message = message.replace("'", "'\"'\"'")
796 os.system(f"/usr/bin/logger -p local7.info -- '{message}'")
799 if __name__ == '__main__':