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(
26 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: Mapping[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:
227 self.counters = 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]
237 f'{record.pathname}+{record.lineno}+{record.levelno}+{record.msg}'
239 count = self.counters[logsite]
240 self.counters[logsite] += 1
241 return count < threshold
244 class DynamicPerScopeLoggingLevelFilter(logging.Filter):
245 """This filter only allows logging messages from an allow list of
246 module names or module:function names. Blocks others.
251 def level_name_to_level(name: str) -> int:
252 numeric_level = getattr(logging, name, None)
253 if not isinstance(numeric_level, int):
254 raise ValueError(f'Invalid level: {name}')
259 default_logging_level: int,
260 per_scope_logging_levels: str,
263 self.valid_levels = set(
264 ['NOTSET', 'DEBUG', 'INFO', 'WARNING', 'ERROR', 'CRITICAL']
266 self.default_logging_level = default_logging_level
267 self.level_by_scope = {}
268 if per_scope_logging_levels is not None:
269 for chunk in per_scope_logging_levels.split(','):
272 f'Malformed lmodule directive: "{chunk}", missing "=". Ignored.',
277 (scope, level) = chunk.split('=')
280 f'Malformed lmodule directive: "{chunk}". Ignored.',
284 scope = scope.strip()
285 level = level.strip().upper()
286 if level not in self.valid_levels:
288 f'Malformed lmodule directive: "{chunk}", bad level. Ignored.',
294 ] = DynamicPerScopeLoggingLevelFilter.level_name_to_level(level)
297 def filter(self, record: logging.LogRecord) -> bool:
298 # First try to find a logging level by scope (--lmodule)
299 if len(self.level_by_scope) > 0:
303 f'{record.module}:{record.funcName}',
304 f':{record.funcName}',
306 level = self.level_by_scope.get(scope, None)
307 if level is not None:
308 if min_level is None or level < min_level:
311 # If we found one, use it instead of the global default level.
312 if min_level is not None:
313 return record.levelno >= min_level
315 # Otherwise, use the global logging level (--logging_level)
316 return record.levelno >= self.default_logging_level
319 # A map from function_identifier -> probability of logging (0.0%..100.0%)
320 probabilistic_logging_levels: Mapping[str, float] = {}
323 def logging_is_probabilistic(probability_of_logging: float) -> Callable:
325 A decorator that indicates that all logging statements within the
326 scope of a particular (marked) function are not deterministic
327 (i.e. they do not always unconditionally log) but rather are
328 probabilistic (i.e. they log N% of the time randomly).
330 Note that this functionality can be disabled (forcing all logged
331 messages to produce output) via the --no_logging_probabilistically
334 This affects *ALL* logging statements within the marked function.
338 def probabilistic_logging_wrapper(f: Callable):
339 import function_utils
341 identifier = function_utils.function_identifier(f)
342 probabilistic_logging_levels[identifier] = probability_of_logging
345 return probabilistic_logging_wrapper
348 class ProbabilisticFilter(logging.Filter):
350 A filter that logs messages probabilistically (i.e. randomly at some
353 This filter only affects logging messages from functions that have
354 been tagged with the @logging_utils.probabilistic_logging decorator.
359 def filter(self, record: logging.LogRecord) -> bool:
360 id1 = f'{record.module}:{record.funcName}'
361 if id1 not in probabilistic_logging_levels:
363 threshold = probabilistic_logging_levels[id1]
364 return (random.random() * 100.0) <= threshold
367 class OnlyInfoFilter(logging.Filter):
369 A filter that only logs messages produced at the INFO logging
370 level. This is used by the logging_info_is_print commandline
371 option to select a subset of the logging stream to send to a
377 def filter(self, record: logging.LogRecord):
378 return record.levelno == logging.INFO
381 class MillisecondAwareFormatter(logging.Formatter):
383 A formatter for adding milliseconds to log messages which, for
384 whatever reason, the default python logger doesn't do.
388 converter = datetime.datetime.fromtimestamp
391 def formatTime(self, record, datefmt=None):
392 ct = MillisecondAwareFormatter.converter(
393 record.created, pytz.timezone("US/Pacific")
396 s = ct.strftime(datefmt)
398 t = ct.strftime("%Y-%m-%d %H:%M:%S")
399 s = "%s,%03d" % (t, record.msecs)
403 def initialize_logging(logger=None) -> logging.Logger:
404 global logging_initialized
405 if logging_initialized:
407 logging_initialized = True
410 logger = logging.getLogger()
412 preexisting_handlers_count = 0
413 assert config.has_been_parsed()
414 if config.config['logging_clear_preexisting_handlers']:
415 while logger.hasHandlers():
416 logger.removeHandler(logger.handlers[0])
417 preexisting_handlers_count += 1
419 if config.config['logging_config_file'] is not None:
420 logging.config.fileConfig('logging.conf')
425 # Global default logging level (--logging_level)
426 default_logging_level = getattr(
427 logging, config.config['logging_level'].upper(), None
429 if not isinstance(default_logging_level, int):
430 raise ValueError('Invalid level: %s' % config.config['logging_level'])
432 if config.config['logging_format']:
433 fmt = config.config['logging_format']
435 if config.config['logging_syslog']:
436 fmt = '%(levelname).1s:%(filename)s[%(process)d]: %(message)s'
438 fmt = '%(levelname).1s:%(asctime)s: %(message)s'
439 if config.config['logging_debug_threads']:
440 fmt = f'%(process)d.%(thread)d|{fmt}'
441 if config.config['logging_debug_modules']:
442 fmt = f'%(filename)s:%(funcName)s:%(lineno)s|{fmt}'
444 if config.config['logging_syslog']:
445 if sys.platform not in ('win32', 'cygwin'):
446 if config.config['logging_syslog_facility']:
448 'LOG_' + config.config['logging_syslog_facility']
450 facility = SysLogHandler.__dict__.get(
451 facility_name, SysLogHandler.LOG_USER
453 handler = SysLogHandler(facility=facility, address='/dev/log')
454 handler.setFormatter(
455 MillisecondAwareFormatter(
457 datefmt=config.config['logging_date_format'],
460 handlers.append(handler)
462 if config.config['logging_filename']:
463 handler = RotatingFileHandler(
464 config.config['logging_filename'],
465 maxBytes=config.config['logging_filename_maxsize'],
466 backupCount=config.config['logging_filename_count'],
468 handler.setFormatter(
469 MillisecondAwareFormatter(
471 datefmt=config.config['logging_date_format'],
474 handlers.append(handler)
476 if config.config['logging_console']:
477 handler = logging.StreamHandler(sys.stderr)
478 handler.setFormatter(
479 MillisecondAwareFormatter(
481 datefmt=config.config['logging_date_format'],
484 handlers.append(handler)
486 if len(handlers) == 0:
487 handlers.append(logging.NullHandler())
489 for handler in handlers:
490 logger.addHandler(handler)
492 if config.config['logging_info_is_print']:
493 handler = logging.StreamHandler(sys.stdout)
494 handler.addFilter(OnlyInfoFilter())
495 logger.addHandler(handler)
497 if config.config['logging_squelch_repeats']:
498 for handler in handlers:
499 handler.addFilter(SquelchRepeatedMessagesFilter())
501 if config.config['logging_probabilistically']:
502 for handler in handlers:
503 handler.addFilter(ProbabilisticFilter())
505 for handler in handlers:
507 DynamicPerScopeLoggingLevelFilter(
508 default_logging_level,
509 config.config['lmodule'],
513 logger.propagate = False
515 if config.config['logging_captures_prints']:
518 global built_in_print
520 def print_and_also_log(*arg, **kwarg):
521 f = kwarg.get('file', None)
526 built_in_print(*arg, **kwarg)
528 builtins.print = print_and_also_log
530 # At this point the logger is ready, handlers are set up,
531 # etc... so log about the logging configuration.
533 level_name = logging._levelToName.get(
534 default_logging_level, str(default_logging_level)
537 f'Initialized global logging; default logging level is {level_name}.'
540 config.config['logging_clear_preexisting_handlers']
541 and preexisting_handlers_count > 0
543 msg = f'Logging cleared {preexisting_handlers_count} global handlers (--logging_clear_preexisting_handlers)'
545 logger.debug(f'Logging format specification is "{fmt}"')
546 if config.config['logging_debug_threads']:
548 '...Logging format spec captures tid/pid (--logging_debug_threads)'
550 if config.config['logging_debug_modules']:
552 '...Logging format spec captures files/functions/lineno (--logging_debug_modules)'
554 if config.config['logging_syslog']:
556 f'Logging to syslog as {facility_name} with priority mapping based on level'
558 if config.config['logging_filename']:
559 logger.debug(f'Logging to filename {config.config["logging_filename"]}')
561 f'...with {config.config["logging_filename_maxsize"]} bytes max file size.'
564 f'...and {config.config["logging_filename_count"]} rotating backup file count.'
566 if config.config['logging_console']:
567 logger.debug('Logging to the console (stderr).')
568 if config.config['logging_info_is_print']:
570 'Logging logger.info messages will be repeated on stdout (--logging_info_is_print)'
572 if config.config['logging_squelch_repeats']:
574 'Logging code allowed to request repeated messages be squelched (--logging_squelch_repeats)'
578 'Logging code forbidden to request messages be squelched; all messages logged (--no_logging_squelch_repeats)'
580 if config.config['logging_probabilistically']:
582 'Logging code is allowed to request probabilistic logging (--logging_probabilistically)'
586 'Logging code is forbidden to request probabilistic logging; messages always logged (--no_logging_probabilistically)'
588 if config.config['lmodule']:
590 f'Logging dynamic per-module logging enabled (--lmodule={config.config["lmodule"]})'
592 if config.config['logging_captures_prints']:
594 'Logging will capture printed data as logger.info messages (--logging_captures_prints)'
599 def get_logger(name: str = ""):
600 logger = logging.getLogger(name)
601 return initialize_logging(logger)
604 def tprint(*args, **kwargs) -> None:
605 """Legacy function for printing a message augmented with thread id
606 still needed by some code. Please use --logging_debug_threads in
610 if config.config['logging_debug_threads']:
611 from thread_utils import current_thread_id
613 print(f'{current_thread_id()}', end="")
614 print(*args, **kwargs)
619 def dprint(*args, **kwargs) -> None:
620 """Legacy function used to print to stderr still needed by some code.
621 Please just use normal logging with --logging_console which
622 accomplishes the same thing in new code.
625 print(*args, file=sys.stderr, **kwargs)
628 class OutputMultiplexer(object):
630 A class that broadcasts printed messages to several sinks (including
631 various logging levels, different files, different file handles,
632 the house log, etc...). See also OutputMultiplexerContext for an
637 class Destination(enum.IntEnum):
638 """Bits in the destination_bitv bitvector. Used to indicate the
639 output destination."""
643 LOG_WARNING = 0x04 # ⎬ Must provide logger to the c'tor.
645 LOG_CRITICAL = 0x10 # ⎭
646 FILENAMES = 0x20 # Must provide a filename to the c'tor.
647 FILEHANDLES = 0x40 # Must provide a handle to the c'tor.
649 ALL_LOG_DESTINATIONS = (
650 LOG_DEBUG | LOG_INFO | LOG_WARNING | LOG_ERROR | LOG_CRITICAL
652 ALL_OUTPUT_DESTINATIONS = 0x8F
656 destination_bitv: int,
659 filenames: Optional[Iterable[str]] = None,
660 handles: Optional[Iterable[io.TextIOWrapper]] = None,
663 logger = logging.getLogger(None)
666 if filenames is not None:
668 open(filename, 'wb', buffering=0) for filename in filenames
671 if destination_bitv & OutputMultiplexer.FILENAMES:
673 "Filenames argument is required if bitv & FILENAMES"
677 if handles is not None:
678 self.h = [handle for handle in handles]
680 if destination_bitv & OutputMultiplexer.Destination.FILEHANDLES:
682 "Handle argument is required if bitv & FILEHANDLES"
686 self.set_destination_bitv(destination_bitv)
688 def get_destination_bitv(self):
689 return self.destination_bitv
691 def set_destination_bitv(self, destination_bitv: int):
692 if destination_bitv & self.Destination.FILENAMES and self.f is None:
694 "Filename argument is required if bitv & FILENAMES"
696 if destination_bitv & self.Destination.FILEHANDLES and self.h is None:
698 "Handle argument is required if bitv & FILEHANDLES"
700 self.destination_bitv = destination_bitv
702 def print(self, *args, **kwargs):
703 from string_utils import sprintf, strip_escape_sequences
705 end = kwargs.pop("end", None)
707 if not isinstance(end, str):
708 raise TypeError("end must be None or a string")
709 sep = kwargs.pop("sep", None)
711 if not isinstance(sep, str):
712 raise TypeError("sep must be None or a string")
714 raise TypeError("invalid keyword arguments to print()")
715 buf = sprintf(*args, end="", sep=sep)
723 self.destination_bitv & self.Destination.FILENAMES
724 and self.f is not None
727 _.write(buf.encode('utf-8'))
731 self.destination_bitv & self.Destination.FILEHANDLES
732 and self.h is not None
738 buf = strip_escape_sequences(buf)
739 if self.logger is not None:
740 if self.destination_bitv & self.Destination.LOG_DEBUG:
741 self.logger.debug(buf)
742 if self.destination_bitv & self.Destination.LOG_INFO:
743 self.logger.info(buf)
744 if self.destination_bitv & self.Destination.LOG_WARNING:
745 self.logger.warning(buf)
746 if self.destination_bitv & self.Destination.LOG_ERROR:
747 self.logger.error(buf)
748 if self.destination_bitv & self.Destination.LOG_CRITICAL:
749 self.logger.critical(buf)
750 if self.destination_bitv & self.Destination.HLOG:
754 if self.f is not None:
759 class OutputMultiplexerContext(OutputMultiplexer, contextlib.ContextDecorator):
761 A context that uses an OutputMultiplexer. e.g.
763 with OutputMultiplexerContext(
764 OutputMultiplexer.LOG_INFO |
765 OutputMultiplexer.LOG_DEBUG |
766 OutputMultiplexer.FILENAMES |
767 OutputMultiplexer.FILEHANDLES,
768 filenames = [ '/tmp/foo.log', '/var/log/bar.log' ],
771 mplex.print("This is a log message!")
777 destination_bitv: OutputMultiplexer.Destination,
793 def __exit__(self, etype, value, traceback) -> bool:
795 if etype is not None:
800 def hlog(message: str) -> None:
801 """Write a message to the house log (syslog facility local7 priority
802 info) by calling /usr/bin/logger. This is pretty hacky but used
803 by a bunch of code. Another way to do this would be to use
804 --logging_syslog and --logging_syslog_facility but I can't
805 actually say that's easier.
808 message = message.replace("'", "'\"'\"'")
809 os.system(f"/usr/bin/logger -p local7.info -- '{message}'")
812 if __name__ == '__main__':